Log4J Errors During Elastic APM Instrumentation

[pkrishnan1 (Panbil K)]

We are trying to instrument Elastic APM(1.35.0) into a weblogic server using Log4J 2.17.1. Getting the below error while the agent is starting up. Can someone help explain why we see this error

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)
DEBUG StatusLogger Unable to retrieve provider from ClassLoader sun.misc.Launcher$AppClassLoader@18b4aac2
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)

[Sylvain_Juge]

Hi @pkrishnan1 , thanks a lot for reporting this issue.

This definitely looks like a bug in the agent during the agent initialization, to help investigation:

• can you provide the Weblogic server version used ?
• is there a security policy in place ? If yes, has it been modified from the defaults ?
• if you are using -javaagent setup option, could you try the CLI attach once the server has started to see if the symptom persists ? If using the CLI attach method works, then it means we might have a rather easy work-around by delaying the agent start.
• By looking at the log4j-api jar path : /nas/apps/bea/applications/i04PME2/lib/log4j-api.jar, can we conclude this dependency is part of the i04PME2 webapp which is a deployed from a war/ear ? If no, is that a kind of "shared lib directory" for the whole Weblogic instance ?

[Sylvain_Juge]

Also, as an alternative to using the "CLI attach" setup method, you could try with adding -Delastic.apm.delay_agent_premain_ms=10000 to your JVM arguments (next to -javaagent optíon). That will delay the agent startup by 10 seconds.

[Sylvain_Juge]

FYI I have opened this issue to track our investigation : potential issue in agent log4j initialization · Issue #2933 · elastic/apm-agent-java · GitHub.

[pkrishnan1 (Panbil K)]

Thanks for looking into this. Here are the responses to your queries

can you provide the Weblogic server version used ?
PK: WL 12.2.1.4.0

is there a security policy in place ? If yes, has it been modified from the defaults ?
PK: Yes, There is the default weblogic security policy used as a Java option. WL_HOME/wlserver/server/lib/weblogic.policy

if you are using -javaagent setup option, could you try the CLI attach once the server has started to see if the symptom persists ? If using the CLI attach method works, then it means we might have a rather easy work-around by delaying the agent start.
PK: I added the delay_agent_premain_ms=10000 key to elasticapm.properties and restarted the Java process and still see the errors.

By looking at the log4j-api jar path : /nas/apps/bea/applications/i04PME2/lib/log4j-api.jar, can we conclude this dependency is part of the i04PME2 webapp which is a deployed from a war/ear ? If no, is that a kind of "shared lib directory" for the whole Weblogic instance ?
PK: That is right. Its a shared library used by all war/ear deployed on the application servers.

[Sylvain_Juge]

Thanks for providing more information on this.

Of course, I forgot the most obvious one, which JDK version are you using here ?
the output of java -version should provide enough detail.

As I am definitely not a Weblogic expert, could you indicate how do you deploy those shared libraries into your server ? For example, are they packaged in a .ear or .war with specific descriptors that allow to make them properly shared ? The reason I am asking this is that there seem to be a specific classloader used here and that could help reproducing the issue.