elastic / elastic/apm-agent-java

potential issue in agent log4j initialization

Offen
#2,933 0 Kommentare 0 Reaktionen 0 zugewiesene Personen Auf GitHub ansehen
agent-java bug
Vorherrschende Sprache
Java
Sterne
593
Forks
337
Ø Merge
1 T. 13 Std.
Gemergte PRs (30 T.)
25

Beschreibung

## 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.

Beitragsleitfaden

Beitragsleitfaden öffnen

Rechercherichtung

Beginne mit co.elastic.apm.agent.logging.LoggingConfiguration#init und Log4jLoggerFactoryBridge#getContext und verfolge dann die im Bericht beschriebenen Log4j ServiceLoader-Aufrufe und das Verhalten von LoaderUtil#getClassLoaders. Reproduziere die Initialisierung nach Möglichkeit unter WebLogic oder mit einem widersprüchlichen log4j-core-Classpath. Erledigt ist die Aufgabe, wenn die Log4j-Initialisierung des Agents nicht mehr fehlschlägt oder diesen Classloader-Konflikt ohne Regressionen ausgibt.

Vom Indexierungsmodell aus dem Issue-Text verfasst.

Bewertung

Tech-Stack
java
Bereich
observability-sre
Issue-Typ
Bug
Schwierigkeit
5/5
Geschätzter Aufwand
Über eine Woche
Aktivitätsstatus
Veraltet
Klarheit
Muss geklärt werden
Anfängerfreundlichkeit
25/100

Neue Issues direkt in Ihr Postfach

Eine kurze Übersicht über anfängerfreundliche GitHub-Issues.