You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Matt Sicker (JIRA)" <ji...@apache.org> on 2018/08/30 16:10:00 UTC
[jira] [Commented] (LOG4J2-2425) Wrong LoggerContext selected by
ClassLoaderContextSelector when using Groovy
[ https://issues.apache.org/jira/browse/LOG4J2-2425?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16597612#comment-16597612 ]
Matt Sicker commented on LOG4J2-2425:
-------------------------------------
While this may not fix the bug at hand, have you looked at using {{LoggerContextRule}} from log4j-core:tests? It provides a JUnit rule you can use (along with a {{ListAppender}}) which make testing logging code a lot easier.
> 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)