logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Nick Williams (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4J2-245) EmptyStackException when logging error through JCL bridge
Date Thu, 09 May 2013 19:39:18 GMT

    [ https://issues.apache.org/jira/browse/LOG4J2-245?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13653088#comment-13653088
] 

Nick Williams commented on LOG4J2-245:
--------------------------------------

Okay, I've done a little analysis. First, it appears that the goal here is to include more
information in the output stack trace than just:

package.Class.method(File:line)

It appears whoever wrote this actually wanted:

package.Class.method(File:line) jar-or-dir:implementation-version

Those last two bits you can't get from the StackTraceElement. You can only get them from the
Class. Since loading the Class from a String isn't very efficient (read: is very slow), the
goal was to use getCallerClass (or the security manager) to get a stack of classes instead
of a stack of StackTraceElements. A cache was put in place to improve things, but getCallerClass
still makes it better.

Now, if I have misunderstood anything here, please let me know, because the rest of this might
not be pertinent. Assuming I'm right...

The first thing I noticed is that Throwable#getStackTrace() and Reflection#getCallerClass(in
loop) will not return the same stack! They will have different classes, or classes out of
order. The stacks will only match up to a certain point, and then they will stop matching
and you'll revert to loading classes manually. Maybe this is okay and was understood, but
I'm not sure how much good it's doing.

The second thing that caught my eyes was this:

if (source != null) {
    final URL locationURL = source.getLocation();
    if (locationURL != null) {
        final String str = locationURL.toString().replace('\\', '/');
        int index = str.lastIndexOf("/");
        if (index >= 0 && index == str.length() - 1) {
            index = str.lastIndexOf("/", index - 1);
            location = str.substring(index + 1);
        } else {
            location = str.substring(index + 1);
        }
    }
}

I think the performance of this can be improved (please check my syntax):

if (source != null) {
    final URL locationURL = source.getLocation();
    if (locationURL != null) {
        // split without limit trims off empty parts, so no need to worry about URL ending
in slash
        final String[] parts = locationURL.toString().split("(\\\\:\/)");
        location = parts[ parts.length - 1];
    }
}

I believe that's an improvement. (I could be wrong; regular expressions aren't always the
answer.)

By the way, I created this: http://mail.openjdk.java.net/pipermail/java-se-8-spec-comments/2013-May/000014.html
                
> 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-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message