elastic / elastic/apm-agent-java
potential issue in agent log4j initialization
- Dominant language
- Java
- Stars
- 594
- Forks
- 338
- Avg merge
- 1d 13h
- Merged PRs (30d)
- 25
Description
## Issue description
A user reported [in our forum](https://discuss.elastic.co/t/log4j-errors-during-elastic-apm-instrumentation/321696) 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.
Contributor guide
Assessment
This issue has not been assessed yet.