Björn Kautler created LOG4J2-2425:
-------------------------------------
Summary: Wrong LoggerContext selected by
ClassLoaderContextSelector when using Groovy
Key: LOG4J2-2425
URL: https://issues.apache.org/jira/browse/LOG4J2-2425
Project: Log4j 2
Issue Type: Bug
Affects Versions: 2.11.0
Reporter: Björn Kautler
I have a Java project that uses log4j for logging.
I test the project using spock framework and thus Groovy code.
In one of the tests I wanted to verify that some messages are logged or are not
logged.
Because of that I queried {{LogManager.getRootLogger()}} and added a
{{WriterAppender}}.
But nothing was logged.
After some debugging I found out, that the {{ClassLoaderContextSelector}} got
the wrong caller class and thus the wrong class loader and thus the wrong
logger context, so the wrong root logger was changed and nothing was logged to
my appender.
I could work-around it by setting {{log4j2.contextSelector =
org.apache.logging.log4j.core.selector.BasicContextSelector}} in
{{log4j.component.properties}}.
The code that determines the called class and thus the caller class loader
needs some Groovy-specific logic to work more reliably and as expected.
Here some examples:
----
The code {{LogManager.getMethod('getRootLogger').invoke(null)}} has the stack
trace
{code}
Breakpoint reached
at
org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:73)
at
org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:228)
at
org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45)
at org.apache.logging.log4j.LogManager.getContext(LogManager.java:174)
at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:648)
at
org.apache.logging.log4j.LogManager.getRootLogger(LogManager.java:682)
at
sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
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.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
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
org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoCachedMethodSite.invoke(PojoMetaMethodSite.java:192)
at
org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:56)
at
org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)
at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:125)
at
org.javacord.core.util.ratelimit.RatelimitManagerTest.$spock_feature_0_0(RatelimitManagerTest.groovy:26)
at
sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
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
org.spockframework.util.ReflectionUtil.invokeMethod(ReflectionUtil.java:188)
at
org.spockframework.runtime.model.MethodInfo.invoke(MethodInfo.java:84)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runFeatureMethod(BaseSpecRunner.java:406)
at
org.spockframework.runtime.BaseSpecRunner.doRunIteration(BaseSpecRunner.java:324)
at
org.spockframework.runtime.BaseSpecRunner$6.invoke(BaseSpecRunner.java:309)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runIteration(BaseSpecRunner.java:288)
at
org.spockframework.runtime.BaseSpecRunner.initializeAndRunIteration(BaseSpecRunner.java:278)
at
org.spockframework.runtime.BaseSpecRunner.runSimpleFeature(BaseSpecRunner.java:269)
at
org.spockframework.runtime.BaseSpecRunner.doRunFeature(BaseSpecRunner.java:263)
at
org.spockframework.runtime.BaseSpecRunner$5.invoke(BaseSpecRunner.java:246)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runFeature(BaseSpecRunner.java:238)
at
org.spockframework.runtime.BaseSpecRunner.runFeatures(BaseSpecRunner.java:188)
at
org.spockframework.runtime.BaseSpecRunner.doRunSpec(BaseSpecRunner.java:98)
at
org.spockframework.runtime.BaseSpecRunner$1.invoke(BaseSpecRunner.java:84)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runSpec(BaseSpecRunner.java:76)
at
org.spockframework.runtime.BaseSpecRunner.run(BaseSpecRunner.java:67)
at org.spockframework.runtime.Sputnik.run(Sputnik.java:63)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at
com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
at
com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
at
com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
at
com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
{code}
which results in the caller class
{{org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoCachedMethodSite}},
while It should be {{org.javacord.core.util.ratelimit.RatelimitManagerTest}},
it would be the correct class loader though which is
{{sun.misc.Launcher$AppClassLoader@18b4aac2}}.
----
The code {{LogManager.rootLogger}} has the stack trace
{code}
Breakpoint reached
at
org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:73)
at
org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:228)
at
org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45)
at org.apache.logging.log4j.LogManager.getContext(LogManager.java:174)
at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:648)
at
org.apache.logging.log4j.LogManager.getRootLogger(LogManager.java:682)
at
sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
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
org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:93)
at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
at groovy.lang.MetaClassImpl.getProperty(MetaClassImpl.java:1855)
at groovy.lang.MetaClassImpl.getProperty(MetaClassImpl.java:3763)
at
org.codehaus.groovy.runtime.callsite.ClassMetaClassGetPropertySite.getProperty(ClassMetaClassGetPropertySite.java:51)
at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.callGetProperty(AbstractCallSite.java:296)
at
org.javacord.core.util.ratelimit.RatelimitManagerTest.$spock_feature_0_0(RatelimitManagerTest.groovy:27)
at
sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
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
org.spockframework.util.ReflectionUtil.invokeMethod(ReflectionUtil.java:188)
at
org.spockframework.runtime.model.MethodInfo.invoke(MethodInfo.java:84)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runFeatureMethod(BaseSpecRunner.java:406)
at
org.spockframework.runtime.BaseSpecRunner.doRunIteration(BaseSpecRunner.java:324)
at
org.spockframework.runtime.BaseSpecRunner$6.invoke(BaseSpecRunner.java:309)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runIteration(BaseSpecRunner.java:288)
at
org.spockframework.runtime.BaseSpecRunner.initializeAndRunIteration(BaseSpecRunner.java:278)
at
org.spockframework.runtime.BaseSpecRunner.runSimpleFeature(BaseSpecRunner.java:269)
at
org.spockframework.runtime.BaseSpecRunner.doRunFeature(BaseSpecRunner.java:263)
at
org.spockframework.runtime.BaseSpecRunner$5.invoke(BaseSpecRunner.java:246)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runFeature(BaseSpecRunner.java:238)
at
org.spockframework.runtime.BaseSpecRunner.runFeatures(BaseSpecRunner.java:188)
at
org.spockframework.runtime.BaseSpecRunner.doRunSpec(BaseSpecRunner.java:98)
at
org.spockframework.runtime.BaseSpecRunner$1.invoke(BaseSpecRunner.java:84)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runSpec(BaseSpecRunner.java:76)
at
org.spockframework.runtime.BaseSpecRunner.run(BaseSpecRunner.java:67)
at org.spockframework.runtime.Sputnik.run(Sputnik.java:63)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at
com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
at
com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
at
com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
at
com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
{code}
which results in the caller class
{{org.codehaus.groovy.reflection.CachedMethod}}, while It should be
{{org.javacord.core.util.ratelimit.RatelimitManagerTest}}, it would be the
correct class loader though which is
{{sun.misc.Launcher$AppClassLoader@18b4aac2}}.
----
The code {{LogManager.getRootLogger()}} has the stack trace
{code}
Breakpoint reached
at
org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:73)
at
org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:228)
at
org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45)
at org.apache.logging.log4j.LogManager.getContext(LogManager.java:174)
at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:648)
at
org.apache.logging.log4j.LogManager.getRootLogger(LogManager.java:682)
at org.apache.logging.log4j.LogManager$getRootLogger.call(Unknown
Source:-1)
at
org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)
at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:117)
at
org.javacord.core.util.ratelimit.RatelimitManagerTest.$spock_feature_0_0(RatelimitManagerTest.groovy:28)
at
sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
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
org.spockframework.util.ReflectionUtil.invokeMethod(ReflectionUtil.java:188)
at
org.spockframework.runtime.model.MethodInfo.invoke(MethodInfo.java:84)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runFeatureMethod(BaseSpecRunner.java:406)
at
org.spockframework.runtime.BaseSpecRunner.doRunIteration(BaseSpecRunner.java:324)
at
org.spockframework.runtime.BaseSpecRunner$6.invoke(BaseSpecRunner.java:309)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runIteration(BaseSpecRunner.java:288)
at
org.spockframework.runtime.BaseSpecRunner.initializeAndRunIteration(BaseSpecRunner.java:278)
at
org.spockframework.runtime.BaseSpecRunner.runSimpleFeature(BaseSpecRunner.java:269)
at
org.spockframework.runtime.BaseSpecRunner.doRunFeature(BaseSpecRunner.java:263)
at
org.spockframework.runtime.BaseSpecRunner$5.invoke(BaseSpecRunner.java:246)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runFeature(BaseSpecRunner.java:238)
at
org.spockframework.runtime.BaseSpecRunner.runFeatures(BaseSpecRunner.java:188)
at
org.spockframework.runtime.BaseSpecRunner.doRunSpec(BaseSpecRunner.java:98)
at
org.spockframework.runtime.BaseSpecRunner$1.invoke(BaseSpecRunner.java:84)
at
org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)
at
org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)
at
org.spockframework.runtime.BaseSpecRunner.runSpec(BaseSpecRunner.java:76)
at
org.spockframework.runtime.BaseSpecRunner.run(BaseSpecRunner.java:67)
at org.spockframework.runtime.Sputnik.run(Sputnik.java:63)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at
com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
at
com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
at
com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
at
com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
{code}
which results in the caller class
{{org.apache.logging.log4j.LogManager$getRootLogger}}, while It should be
{{org.javacord.core.util.ratelimit.RatelimitManagerTest}}, here it gives the
wrong class loader {{sun.misc.Launcher$AppClassLoader@18b4aac2}} which is where
I had the problem and spent hours finding out why nothing gets logged to my
appender.
----
I think there is some special-casing needed for the dynamic features of Groovy.
I guess something like all classes named {{\.groovy\..\*\.callsite\.}},
{{^groovy\.lang\.}} and {{\.groovy\..\*\.reflection\.}} and all classes loaded
by a class loader named {{\.groovy\..\*\.callsite\.}} should be discarded when
determining the caller class or something like that. I think at least for my
three examples this would result in the correct outcome.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
