[
https://issues.apache.org/jira/browse/LOG4J2-2425?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16604730#comment-16604730
]
Matt Sicker commented on LOG4J2-2425:
-------------------------------------
In this scenario, it may be that the basic context selector is your best bet
here. It's been a while since I've looked closely through this code, but it
seems like the class loader context selector will try to use a parent-first
context strategy (similar to how classes are loaded in web apps). If you use
the async context selector, you get the same behavior.
Perhaps unit testing class loader hierarchies work differently? Maybe this
could be a default context selector to use when running in JUnit or similar.
> 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
> {{log4j2.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)
