[
https://issues.apache.org/jira/browse/LOG4J2-2425?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16597656#comment-16597656
]
Björn Kautler commented on LOG4J2-2425:
---------------------------------------
Ah, nice, thanks.
I know how to depend on non-standard artifacts, but the "great" new
MavenCentral look 'n' feel doesn't show the artifacts right away anymore and I
forgot to double-check whether it is there.
I'll give it a try.
> 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)
