potential issue in agent log4j initialization

[SylvainJuge]

Issue description

A user reported in our forum the following exception when the agent starts:

DEBUG StatusLogger Unable to retrieve provider from ClassLoader PolicyClassLoader 'weblogic-launcher' @64485a47 {file:/nas/apps/bea/applications/i04PME2/lib/log4j-api.jar file:/nas/apps/bea/applications/i04PME2/lib/log4j-core.jar ... (671 more)}
java.util.ServiceConfigurationError: org.apache.logging.log4j.spi.Provider: Provider org.apache.logging.log4j.core.impl.Log4jProvider not a subtype
at java.util.ServiceLoader.fail(ServiceLoader.java:239)
at java.util.ServiceLoader.access$300(ServiceLoader.java:185)
at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:376)
at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
at java.util.ServiceLoader$1.next(ServiceLoader.java:480)
at org.apache.logging.log4j.util.ProviderUtil.loadProviders(ProviderUtil.java:109)
at org.apache.logging.log4j.util.ProviderUtil.(ProviderUtil.java:68)
at org.apache.logging.log4j.util.ProviderUtil.lazyInit(ProviderUtil.java:150)
at org.apache.logging.log4j.util.ProviderUtil.hasProviders(ProviderUtil.java:134)
at org.apache.logging.log4j.spi.ThreadContextMapFactory.createThreadContextMap(ThreadContextMapFactory.java:99)
at org.apache.logging.log4j.ThreadContext.init(ThreadContext.java:225)
at org.apache.logging.log4j.ThreadContext.(ThreadContext.java:203)
at org.apache.logging.log4j.core.impl.ContextDataInjectorFactory.createDefaultInjector(ContextDataInjectorFactory.java:83)
at org.apache.logging.log4j.core.impl.ContextDataInjectorFactory.createInjector(ContextDataInjectorFactory.java:67)
at org.apache.logging.log4j.core.lookup.ContextMapLookup.(ContextMapLookup.java:34)
at org.apache.logging.log4j.core.lookup.Interpolator.(Interpolator.java:125)
at org.apache.logging.log4j.core.lookup.Interpolator.(Interpolator.java:90)
at org.apache.logging.log4j.core.config.ConfigurationFactory.(ConfigurationFactory.java:134)
at org.apache.logging.log4j.core.config.ConfigurationFactory$Factory.(ConfigurationFactory.java:355)
at org.apache.logging.log4j.core.config.ConfigurationFactory$Factory.(ConfigurationFactory.java:355)
at org.apache.logging.log4j.core.config.ConfigurationFactory.(ConfigurationFactory.java:132)
at co.elastic.apm.agent.logging.LoggingConfiguration.init(LoggingConfiguration.java:285)
at co.elastic.apm.agent.impl.ElasticApmTracerBuilder.(ElasticApmTracerBuilder.java:100)
at co.elastic.apm.agent.bci.ElasticApmAgent.initialize(ElasticApmAgent.java:154)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at co.elastic.apm.agent.premain.AgentMain.loadAndInitializeAgent(AgentMain.java:160)
at co.elastic.apm.agent.premain.AgentMain.init(AgentMain.java:101)
at co.elastic.apm.agent.premain.AgentMain.premain(AgentMain.java:50)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:386)
at sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:401)

For now we don't know much from the environment outside the fact that it is using Weblogic application server.

I did not manage to reproduce it directly, but by looking at the stack trace it seems that:

• our log4j initialization is the trigger
• there seems to be another log4j-core.jar in the classpath (maybe in the bootstrap classpath), so there is a potential conflict with the copy within the agent jar.

Here are my observations so far:

• During the log4j initialization and also later when doing individual logger lookups, there are multiple calls to the ServiceLoader.
• log4j iterates over multiple classloaders when doing lookups using org.apache.logging.log4j.util.LoaderUtil#getClassLoaders
• we can avoid a few lookups by setting the following environment variables:
  • log4j2.ContextDataInjector = org.apache.logging.log4j.core.impl.ThreadContextDataInjector.ForCopyOnWriteThreadContextMap (not 100% sure about the last . or using $ for inner class).
  • log4j2.loggerContextFactory = org.apache.logging.log4j.core.impl.Log4jContextFactory
  • log4j2.threadContextMap = org.apache.logging.log4j.spi.DefaultThreadContextMap
• those environment variables have to be set in co.elastic.apm.agent.logging.LoggingConfiguration#init and in co.elastic.apm.agent.logging.Log4jLoggerFactoryBridge#getContext to wrap the LogManager.getContext() call.
• when each individual logger is initialized, there are still calls to org.apache.logging.log4j.util.LoaderUtil#getClassLoaders, so maybe the "right" way to ensure that the agent never tries to load classes from other classloaders would be to instrument this getClassLoaders method and only include the agent class loaders.