[
https://issues.apache.org/jira/browse/LOG4J2-245?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13653162#comment-13653162
]
Nick Williams commented on LOG4J2-245:
--------------------------------------
Ralph, I need to correct something you said. The result of calling
getCallerClass() will almost never return the same stack trace as
Throwable#getStackTrace() in "the real world," even if you account for the
gaps; but you're right, it won't have different /order/. Consider this stack:
- Thread.run()
- Parent.teach()
- ClassA.foo()
- ClassB.bar()
- Child.misbehave() throws PitchFitException
Here, Parent#teach() catches the exception thrown in Child#misbehave(). The
stack trace is:
PitchFitException: I want my money now!
at Child.misbehave()
at ClassB.bar()
at ClassA.foo()
at Parent.teach()
at Thread.run()
Now Parent#teach() calls Logger#error("Message", e); When ThrowableProxy is
created and calls getCallingClass, the stack looks like this:
- Thread.run()
- Parent.teach()
- Logger.error()
- Logger.log()
- CoreClass.doSomething()
- ThrowableProxy.<init>()
- ThrowableProxy.getCurrentStack()
- Reflection.getCallingClass()
As a result, the java.util.Stack creating from calling getCallingClass looks
like this:
Reflection
ThrowableProxy
ThrowableProxy
CoreClass
Logger
Logger
Parent
Thread
When the code runs to line them up, it will only match Thread and Parent. All
the other classes it will have to look up manually. In the best case scenario,
only 2 or 3 elements of the stack trace will have to be looked up "the hard
way." In the worst case scenario, you have 3 or 4 causes and each has 30 or 40
elements that have to be looked up the hard way.
If you test this in a simple program, it will APPEAR to perform much better
because you're creating the Exception in the same method that you're creating
the ThrowableProxy, so ALL of the stack will line up. But in the real world,
the exception stack trace will look very different from the real stack trace,
and this performance-improving code won't do a whole lot, IMO.
Does that make sense?
> EmptyStackException when logging error through JCL bridge
> ---------------------------------------------------------
>
> Key: LOG4J2-245
> URL: https://issues.apache.org/jira/browse/LOG4J2-245
> Project: Log4j 2
> Issue Type: Bug
> Components: Core, JCL Bridge
> Affects Versions: 2.0-beta5, 2.0-beta6
> Reporter: Nick Williams
> Priority: Blocker
>
> Possibly affects earlier versions, too, but I did not check.
> beta5 and beta6 are both unusable with Spring Framework. Any time an error
> gets logged through log4j-jcl bridge using Spring, the error below appears in
> the Tomcat log, masking the error that Spring was trying to log and making it
> very difficult to figure out what happened. I've also included my
> configuration file below the stack trace. The root error is happening on
> Tomcat 6 due to Spring bug, and that root problem is unimportant. The
> important problem is the Log4j error that masks it.
> SEVERE: Exception sending context initialized event to listener instance of
> class org.springframework.web.context.ContextLoaderListener
> java.util.EmptyStackException
> at java.util.Stack.peek(Stack.java:102)
> at
> org.apache.logging.log4j.core.impl.ThrowableProxy.resolvePackageData(ThrowableProxy.java:339)
> at
> org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:71)
> at
> org.apache.logging.log4j.core.impl.Log4jLogEvent.<init>(Log4jLogEvent.java:110)
> at
> org.apache.logging.log4j.core.impl.Log4jLogEvent.<init>(Log4jLogEvent.java:81)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.createEvent(LoggerConfig.java:423)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:344)
> at org.apache.logging.log4j.core.Logger.log(Logger.java:110)
> at
> org.apache.logging.log4j.spi.AbstractLoggerWrapper.log(AbstractLoggerWrapper.java:55)
> at
> org.apache.logging.log4j.spi.AbstractLogger.error(AbstractLogger.java:539)
> at
> org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:319)
> at
> org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:112)
> at
> org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4765)
> at
> org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5210)
> at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
> at
> org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:726)
> at
> org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:702)
> at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:698)
> at
> org.apache.catalina.startup.HostConfig.manageApp(HostConfig.java:1491)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:491)
> at
> org.apache.tomcat.util.modeler.BaseModelMBean.invoke(BaseModelMBean.java:300)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819)
> at
> com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:792)
> at
> org.apache.catalina.mbeans.MBeanFactory.createStandardContext(MBeanFactory.java:468)
> at
> org.apache.catalina.mbeans.MBeanFactory.createStandardContext(MBeanFactory.java:415)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:491)
> at
> org.apache.tomcat.util.modeler.BaseModelMBean.invoke(BaseModelMBean.java:300)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819)
> at
> com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:792)
> at
> javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1465)
> at
> javax.management.remote.rmi.RMIConnectionImpl.access$300(RMIConnectionImpl.java:75)
> at
> javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1306)
> at
> javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1398)
> at
> javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:827)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:491)
> at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:322)
> at sun.rmi.transport.Transport$1.run(Transport.java:177)
> at sun.rmi.transport.Transport$1.run(Transport.java:174)
> at java.security.AccessController.doPrivileged(Native Method)
> at sun.rmi.transport.Transport.serviceCall(Transport.java:173)
> at
> sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:556)
> at
> sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:811)
> at
> sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:670)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
> <?xml version="1.0" encoding="UTF-8"?>
> <configuration status="WARN">
> <appenders>
> <Console name="Console" target="SYSTEM_OUT">
> <PatternLayout
> pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} -
> %msg%n"/>
> </Console>
> <RollingFile name="WroxFileAppender"
> fileName="../logs/application.log"
> filePattern="../logs/application-%d{MM-dd-yyyy}-%i.log">
> <PatternLayout>
> <pattern>%d{HH:mm:ss.SSS} [%t] %X{id} %X{username} %-5level
> %c{36} %l: %msg%n</pattern>
> </PatternLayout>
> <Policies>
> <SizeBasedTriggeringPolicy size="10 MB" />
> </Policies>
> <DefaultRolloverStrategy min="1" max="4" />
> </RollingFile>
> </appenders>
> <loggers>
> <root level="warn">
> <appender-ref ref="Console" />
> <appender-ref ref="WroxFileAppender" />
> </root>
> <logger name="com.wrox" level="info" />
> <logger name="org.apache" level="info" />
> <logger name="org.springframework" level="info" />
> </loggers>
> </configuration>
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
