[
https://issues.apache.org/jira/browse/LOG4J2-2425?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16597987#comment-16597987
]
Björn Kautler commented on LOG4J2-2425:
---------------------------------------
Hm, do you maybe also have a good tipp for me on how to use it [~jvz]?
The problem I'm currently facing is, that now each test method opens a separate
log context.
Our loggers are usually held in static fields, I think this is common practice,
isn't it?
And even if not it is surely commonly done like that often.
So now the problem is, to test this I copied the test method to have them twice
identically.
The first one is run successfully, providing some log events.
The second one does not.
The loggers in the static fields are from the "old" context and do not log
anything, or at least not to the appender I get from the rule.
Of course with two test methods in one test class I could use a class rule
instead and clear the list appender before the test method, but then I would
have the same problem between multiple test classes.
> 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
> Priority: Major
>
> 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)
