Log4j 2
  1. Log4j 2
  2. LOG4J2-245

EmptyStackException when logging exceptions with Log4J2 in Java 8

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta5, 2.0-beta6
    • Fix Version/s: 2.0-beta7
    • Component/s: Core, JCL Bridge
    • Labels:
      None
    • Environment:

      Java 8 (1.8.0-ea-b88)

      Description

      [Note: the description below is the original error report. After analysis it turned out that this problem will happen unconditionally when logging a Throwable on a Java 8 JVM.]

      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>

        Issue Links

          Activity

          Hide
          Remko Popma added a comment -

          Nick, if you need something fast, I cannot commit from work, but here is a patch that I believe will fix the issue.
          Can you build and see if this fixes the issue?

          Index: D:/data/workspace-4.2.1/log4j2/core/src/main/java/org/apache/logging/log4j/core/impl/ThrowableProxy.java
          ===================================================================
          — D:/data/workspace-4.2.1/log4j2/core/src/main/java/org/apache/logging/log4j/core/impl/ThrowableProxy.java (revision 1480220)
          +++ D:/data/workspace-4.2.1/log4j2/core/src/main/java/org/apache/logging/log4j/core/impl/ThrowableProxy.java (working copy)
          @@ -336,19 +336,19 @@
          stackLength = stackTrace.length;
          }
          final StackTracePackageElement[] packageArray = new StackTracePackageElement[stackLength];

          • Class<?> clazz = stack.peek();
            + Class<?> clazz = stack.isEmpty() ? null : stack.peek();
            ClassLoader lastLoader = null;
            for (int i = stackLength - 1; i >= 0; --i) {
            final String className = stackTrace[i].getClassName();
            // The stack returned from getCurrentStack will be missing entries for java.lang.reflect.Method.invoke()
            // and its implementation. The Throwable might also contain stack entries that are no longer
            // present as those methods have returned.
          • if (className.equals(clazz.getName())) {
            + if (!stack.isEmpty() && className.equals(clazz.getName())) { final CacheEntry entry = resolvePackageElement(clazz, true); packageArray[i] = entry.element; lastLoader = entry.loader; stack.pop(); - clazz = stack.peek(); + clazz = stack.isEmpty() ? null : stack.peek(); }

            else {
            if (map.containsKey(className)) {
            final CacheEntry entry = map.get(className);

          Show
          Remko Popma added a comment - Nick, if you need something fast, I cannot commit from work, but here is a patch that I believe will fix the issue. Can you build and see if this fixes the issue? Index: D:/data/workspace-4.2.1/log4j2/core/src/main/java/org/apache/logging/log4j/core/impl/ThrowableProxy.java =================================================================== — D:/data/workspace-4.2.1/log4j2/core/src/main/java/org/apache/logging/log4j/core/impl/ThrowableProxy.java (revision 1480220) +++ D:/data/workspace-4.2.1/log4j2/core/src/main/java/org/apache/logging/log4j/core/impl/ThrowableProxy.java (working copy) @@ -336,19 +336,19 @@ stackLength = stackTrace.length; } final StackTracePackageElement[] packageArray = new StackTracePackageElement [stackLength] ; Class<?> clazz = stack.peek(); + Class<?> clazz = stack.isEmpty() ? null : stack.peek(); ClassLoader lastLoader = null; for (int i = stackLength - 1; i >= 0; --i) { final String className = stackTrace [i] .getClassName(); // The stack returned from getCurrentStack will be missing entries for java.lang.reflect.Method.invoke() // and its implementation. The Throwable might also contain stack entries that are no longer // present as those methods have returned. if (className.equals(clazz.getName())) { + if (!stack.isEmpty() && className.equals(clazz.getName())) { final CacheEntry entry = resolvePackageElement(clazz, true); packageArray[i] = entry.element; lastLoader = entry.loader; stack.pop(); - clazz = stack.peek(); + clazz = stack.isEmpty() ? null : stack.peek(); } else { if (map.containsKey(className)) { final CacheEntry entry = map.get(className);
          Hide
          Nick Williams added a comment -

          Shouldn't

          if (!stack.isEmpty() && className.equals(clazz.getName())) {

          Just be

          if (clazz != null && className.equals(clazz.getName())) {

          It achieves the same thing but doesn't involve the overhead of a method call.

          Also, why does this only happen through the JCL bridge? Why doesn't it happen when I call log.error() with an exception in my code? It seems like knowing the answer to that question might be important. :-/

          Show
          Nick Williams added a comment - Shouldn't if (!stack.isEmpty() && className.equals(clazz.getName())) { Just be if (clazz != null && className.equals(clazz.getName())) { It achieves the same thing but doesn't involve the overhead of a method call. Also, why does this only happen through the JCL bridge? Why doesn't it happen when I call log.error() with an exception in my code? It seems like knowing the answer to that question might be important. :-/
          Hide
          Remko Popma added a comment -

          Nick, I could be paranoid but the check against an empty stack guards against the possibility of the call to stack.pop() throwing another EmptyStackException on line 350.

          I don't think it is caused by JCL bridge. From the stack trace it looks like this is a JMX remote method invocation. Which means that a SecurityManager is set. If on top of that, the sun.reflect.Reflection class could not be loaded, then the Stack object returned by #getCurrentStack() will be an empty Stack object.

          You can confirm my hypothesis by setting status="DEBUG" in your log4j2.xml config. I suspect you will see this line:
          "sun.reflect.Reflection is not installed".

          Show
          Remko Popma added a comment - Nick, I could be paranoid but the check against an empty stack guards against the possibility of the call to stack.pop() throwing another EmptyStackException on line 350. I don't think it is caused by JCL bridge. From the stack trace it looks like this is a JMX remote method invocation. Which means that a SecurityManager is set. If on top of that, the sun.reflect.Reflection class could not be loaded, then the Stack object returned by #getCurrentStack() will be an empty Stack object. You can confirm my hypothesis by setting status="DEBUG" in your log4j2.xml config. I suspect you will see this line: "sun.reflect.Reflection is not installed".
          Hide
          Remko Popma added a comment -

          About performance though, I wanted to do some profiling anyway, and this class was already high on my list of Persons Of Interest.
          I won't know for sure until I've done the profiling, but from the looks of it this class is doing quite a bit of (expensive?) work for every single event.
          However, the fruits of all that labor are only enjoyed by configurations with a RootThrowablePattern

          {"rEx", "rThrowable", "rException" }

          or an ExtendedThrowablePattern

          {"xEx", "xThrowable", "xException" }

          .

          I could be wrong and constructing a ThrowableProxy may be quite cheap, I won't know until I've profiled it. But it may be an opportunity for a performance improvement.

          Show
          Remko Popma added a comment - About performance though, I wanted to do some profiling anyway, and this class was already high on my list of Persons Of Interest. I won't know for sure until I've done the profiling, but from the looks of it this class is doing quite a bit of (expensive?) work for every single event. However, the fruits of all that labor are only enjoyed by configurations with a RootThrowablePattern {"rEx", "rThrowable", "rException" } or an ExtendedThrowablePattern {"xEx", "xThrowable", "xException" } . I could be wrong and constructing a ThrowableProxy may be quite cheap, I won't know until I've profiled it. But it may be an opportunity for a performance improvement.
          Hide
          Nick Williams added a comment -

          You are paranoid ... and slightly incorrect:

          1) The way the Stack is created and used here, it is on the Java stack during the execution of the constructor, it is local, it is not held by any other objects, and it cannot be concurrently modified. So there is no danger of stack.pop() throwing another ESE if class != null.
          2) If the Stack WERE a reference shared by other objects (it is not, to be clear), calling stack.isEmpty() again STILL would not guard against an ESE. You would need to synchronize access to the stack to prevent this completely. However, since it's only local, you don't need to synchronize.

          Also, that was a good hypothesis, but it did not hold. The reason JMX was being used is that IntelliJ deploys projects using JMX. So I deployed the project and started Tomcat manually, instead, which removed JMX from the equation. Stack trace is different, problem still exists.

          Nick

          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.deployDirectory(HostConfig.java:1056)
          at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1610)
          at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
          at java.util.concurrent.FutureTask.run(FutureTask.java:262)
          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)

          Show
          Nick Williams added a comment - You are paranoid ... and slightly incorrect: 1) The way the Stack is created and used here, it is on the Java stack during the execution of the constructor, it is local, it is not held by any other objects, and it cannot be concurrently modified. So there is no danger of stack.pop() throwing another ESE if class != null. 2) If the Stack WERE a reference shared by other objects (it is not, to be clear), calling stack.isEmpty() again STILL would not guard against an ESE. You would need to synchronize access to the stack to prevent this completely. However, since it's only local, you don't need to synchronize. Also, that was a good hypothesis, but it did not hold. The reason JMX was being used is that IntelliJ deploys projects using JMX. So I deployed the project and started Tomcat manually, instead, which removed JMX from the equation. Stack trace is different, problem still exists. Nick 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.deployDirectory(HostConfig.java:1056) at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1610) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) 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)
          Hide
          Remko Popma added a comment -

          First, did the modification fix the issue?

          Second, (on root cause investigation) if you set status="DEBUG" in your log4j2.xml config, do you see these lines?
          sun.reflect.Reflection is not installed
          Unable to install security manager <exception>

          Show
          Remko Popma added a comment - First, did the modification fix the issue? Second, (on root cause investigation) if you set status="DEBUG" in your log4j2.xml config, do you see these lines? sun.reflect.Reflection is not installed Unable to install security manager <exception>
          Hide
          Nick Williams added a comment -

          Unfortunately, I cannot easily test the modification because of the environment I'm running in. I'm stuck with what's in Maven repositories. However, I think we have a bigger problem...

          It is now happening without JCL. ANY time I log a Throwable I'm getting the following ESE. This is a change from a few weeks ago. Also, I set status="DEBUG" and its output is below the ESE. I do not see "sun.reflect.Reflection is not installed" or "Unable to install security manager," but I DO see "Jansi is not installed." Even if your modification DID work (again, I can't test it), all exceptions logged would be missing data in their stack trace it appears.

          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.AbstractLogger.error(AbstractLogger.java:576)
          at com.wrox.config.Bootstrap.onStartup(Bootstrap.java:21)
          at org.springframework.web.SpringServletContainerInitializer.onStartup(SpringServletContainerInitializer.java:180)
          at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5199)
          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.deployDirectory(HostConfig.java:1056)
          at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1610)
          at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
          at java.util.concurrent.FutureTask.run(FutureTask.java:262)
          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)

          2013-05-09 07:26:03,309 DEBUG Generated plugins in 0.000018300 seconds
          2013-05-09 07:26:03,310 DEBUG Generated plugins in 0.000012200 seconds
          2013-05-09 07:26:03,311 DEBUG Generated plugins in 0.000014800 seconds
          2013-05-09 07:26:03,312 DEBUG Generated plugins in 0.000012100 seconds
          2013-05-09 07:26:03,313 DEBUG Generated plugins in 0.000025000 seconds
          2013-05-09 07:26:03,313 DEBUG Generated plugins in 0.000012800 seconds
          2013-05-09 07:26:03,314 DEBUG Generated plugins in 0.000011900 seconds
          2013-05-09 07:26:03,315 DEBUG Generated plugins in 0.000012500 seconds
          2013-05-09 07:26:03,316 DEBUG Generated plugins in 0.000015100 seconds
          2013-05-09 07:26:03,318 DEBUG Generated plugins in 0.000018200 seconds
          2013-05-09 07:26:03,319 DEBUG Generated plugins in 0.000015500 seconds
          2013-05-09 07:26:03,320 DEBUG Generated plugins in 0.000015600 seconds
          2013-05-09 07:26:03,320 DEBUG Generated plugins in 0.000013400 seconds
          2013-05-09 07:26:03,321 DEBUG Generated plugins in 0.000013100 seconds
          2013-05-09 07:26:03,322 DEBUG Generated plugins in 0.000013600 seconds
          2013-05-09 07:26:03,323 DEBUG Generated plugins in 0.000012100 seconds
          2013-05-09 07:26:03,334 DEBUG Calling createLayout on class org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout with params(pattern="%d

          {HH:mm:ss.SSS}

          [%t] %-5level %logger

          {36} - %msg%n", Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null, charset="null")
          2013-05-09 07:26:03,335 DEBUG Generated plugins in 0.000031700 seconds
          2013-05-09 07:26:03,337 DEBUG Calling createAppender on class org.apache.logging.log4j.core.appender.ConsoleAppender for element Console with params(PatternLayout(%d{HH:mm:ss.SSS} [%t] %-5level %logger{36}

          - %msg%n), null, target="SYSTEM_OUT", name="Console", follow="null", suppressExceptions="null")
          2013-05-09 07:26:03,339 DEBUG Jansi is not installed
          2013-05-09 07:26:03,340 DEBUG Calling createLayout on class org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout with params(pattern="%d

          {HH:mm:ss.SSS}

          [%t] %X

          {id} %X{username} %-5level %c{36} %l: %msg%n", Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null, charset="null")
          2013-05-09 07:26:03,341 DEBUG Calling createPolicy on class org.apache.logging.log4j.core.appender.rolling.SizeBasedTriggeringPolicy for element SizeBasedTriggeringPolicy with params(size="10 MB")
          2013-05-09 07:26:03,343 DEBUG Calling createPolicy on class org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy for element Policies with params(policies={SizeBasedTriggeringPolicy(size=10485760)})
          2013-05-09 07:26:03,344 DEBUG Calling createStrategy on class org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy for element DefaultRolloverStrategy with params(max="4", min="1", fileIndex="null", Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml))
          2013-05-09 07:26:03,346 DEBUG Calling createAppender on class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile with params(fileName="../logs/application.log", filePattern="../logs/application-%d{MM-dd-yyyy}-%i.log", append="null", name="WroxFileAppender", bufferedIO="null", immediateFlush="null", Policies(CompositeTriggeringPolicy{SizeBasedTriggeringPolicy(size=10485760)}), DefaultRolloverStrategy(DefaultRolloverStrategy(min=1, max=4)), PatternLayout(%d{HH:mm:ss.SSS} [%t] %X{id}

          %X

          {username}

          %-5level %c

          {36}

          %l: %msg%n),null, suppressExceptions="null", advertise="null", advertiseURI="null", Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml))
          2013-05-09 07:26:03,350 DEBUG Starting RollingFileManager ../logs/application.log
          2013-05-09 07:26:03,353 DEBUG Generated plugins in 0.000017900 seconds
          2013-05-09 07:26:03,355 DEBUG Calling createAppenders on class org.apache.logging.log4j.core.config.plugins.AppendersPlugin for element appenders with params(appenders=

          {Console, WroxFileAppender}

          )
          2013-05-09 07:26:03,356 DEBUG Generated plugins in 0.000026800 seconds
          2013-05-09 07:26:03,358 DEBUG Calling createAppenderRef on class org.apache.logging.log4j.core.config.AppenderRef for element appender-ref with params(ref="Console", level="null", null)
          2013-05-09 07:26:03,360 DEBUG Calling createAppenderRef on class org.apache.logging.log4j.core.config.AppenderRef for element appender-ref with params(ref="WroxFileAppender", level="null", null)
          2013-05-09 07:26:03,362 DEBUG Calling createLogger on class org.apache.logging.log4j.core.config.LoggerConfig$RootLogger for element root with params(additivity="null", level="warn", includeLocation="null", appender-ref=

          {org.apache.logging.log4j.core.config.AppenderRef@39f14d85, org.apache.logging.log4j.core.config.AppenderRef@15fc1bda}

          , properties={}, Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null)
          2013-05-09 07:26:03,364 DEBUG Calling createLogger on class org.apache.logging.log4j.core.config.LoggerConfig for element logger with params(additivity="null",level="info", name="com.wrox", includeLocation="null", appender-ref={}, properties={}, Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null)
          2013-05-09 07:26:03,366 DEBUG Calling createLogger on class org.apache.logging.log4j.core.config.LoggerConfig for element logger with params(additivity="null",level="info", name="org.apache", includeLocation="null", appender-ref={}, properties={}, Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null)
          2013-05-09 07:26:03,370 DEBUG Calling createLogger on class org.apache.logging.log4j.core.config.LoggerConfig for element logger with params(additivity="null",level="info", name="org.springframework", includeLocation="null", appender-ref={}, properties={}, Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null)
          2013-05-09 07:26:03,372 DEBUG Calling createLoggers on class org.apache.logging.log4j.core.config.plugins.LoggersPlugin for element loggers with params(loggers=

          {root, com.wrox, org.apache, org.springframework}

          )
          2013-05-09 07:26:03,375 DEBUG Reconfiguration completed

          Show
          Nick Williams added a comment - Unfortunately, I cannot easily test the modification because of the environment I'm running in. I'm stuck with what's in Maven repositories. However, I think we have a bigger problem... It is now happening without JCL. ANY time I log a Throwable I'm getting the following ESE. This is a change from a few weeks ago. Also, I set status="DEBUG" and its output is below the ESE. I do not see "sun.reflect.Reflection is not installed" or "Unable to install security manager," but I DO see "Jansi is not installed." Even if your modification DID work (again, I can't test it), all exceptions logged would be missing data in their stack trace it appears. 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.AbstractLogger.error(AbstractLogger.java:576) at com.wrox.config.Bootstrap.onStartup(Bootstrap.java:21) at org.springframework.web.SpringServletContainerInitializer.onStartup(SpringServletContainerInitializer.java:180) at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5199) 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.deployDirectory(HostConfig.java:1056) at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1610) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) 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) 2013-05-09 07:26:03,309 DEBUG Generated plugins in 0.000018300 seconds 2013-05-09 07:26:03,310 DEBUG Generated plugins in 0.000012200 seconds 2013-05-09 07:26:03,311 DEBUG Generated plugins in 0.000014800 seconds 2013-05-09 07:26:03,312 DEBUG Generated plugins in 0.000012100 seconds 2013-05-09 07:26:03,313 DEBUG Generated plugins in 0.000025000 seconds 2013-05-09 07:26:03,313 DEBUG Generated plugins in 0.000012800 seconds 2013-05-09 07:26:03,314 DEBUG Generated plugins in 0.000011900 seconds 2013-05-09 07:26:03,315 DEBUG Generated plugins in 0.000012500 seconds 2013-05-09 07:26:03,316 DEBUG Generated plugins in 0.000015100 seconds 2013-05-09 07:26:03,318 DEBUG Generated plugins in 0.000018200 seconds 2013-05-09 07:26:03,319 DEBUG Generated plugins in 0.000015500 seconds 2013-05-09 07:26:03,320 DEBUG Generated plugins in 0.000015600 seconds 2013-05-09 07:26:03,320 DEBUG Generated plugins in 0.000013400 seconds 2013-05-09 07:26:03,321 DEBUG Generated plugins in 0.000013100 seconds 2013-05-09 07:26:03,322 DEBUG Generated plugins in 0.000013600 seconds 2013-05-09 07:26:03,323 DEBUG Generated plugins in 0.000012100 seconds 2013-05-09 07:26:03,334 DEBUG Calling createLayout on class org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout with params(pattern="%d {HH:mm:ss.SSS} [%t] %-5level %logger {36} - %msg%n", Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null, charset="null") 2013-05-09 07:26:03,335 DEBUG Generated plugins in 0.000031700 seconds 2013-05-09 07:26:03,337 DEBUG Calling createAppender on class org.apache.logging.log4j.core.appender.ConsoleAppender for element Console with params(PatternLayout(%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n), null, target="SYSTEM_OUT", name="Console", follow="null", suppressExceptions="null") 2013-05-09 07:26:03,339 DEBUG Jansi is not installed 2013-05-09 07:26:03,340 DEBUG Calling createLayout on class org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout with params(pattern="%d {HH:mm:ss.SSS} [%t] %X {id} %X{username} %-5level %c{36} %l: %msg%n", Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null, charset="null") 2013-05-09 07:26:03,341 DEBUG Calling createPolicy on class org.apache.logging.log4j.core.appender.rolling.SizeBasedTriggeringPolicy for element SizeBasedTriggeringPolicy with params(size="10 MB") 2013-05-09 07:26:03,343 DEBUG Calling createPolicy on class org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy for element Policies with params(policies={SizeBasedTriggeringPolicy(size=10485760)}) 2013-05-09 07:26:03,344 DEBUG Calling createStrategy on class org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy for element DefaultRolloverStrategy with params(max="4", min="1", fileIndex="null", Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml)) 2013-05-09 07:26:03,346 DEBUG Calling createAppender on class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile with params(fileName="../logs/application.log", filePattern="../logs/application-%d{MM-dd-yyyy}-%i.log", append="null", name="WroxFileAppender", bufferedIO="null", immediateFlush="null", Policies(CompositeTriggeringPolicy{SizeBasedTriggeringPolicy(size=10485760)}), DefaultRolloverStrategy(DefaultRolloverStrategy(min=1, max=4)), PatternLayout(%d{HH:mm:ss.SSS} [%t] %X{id} %X {username} %-5level %c {36} %l: %msg%n),null, suppressExceptions="null", advertise="null", advertiseURI="null", Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml)) 2013-05-09 07:26:03,350 DEBUG Starting RollingFileManager ../logs/application.log 2013-05-09 07:26:03,353 DEBUG Generated plugins in 0.000017900 seconds 2013-05-09 07:26:03,355 DEBUG Calling createAppenders on class org.apache.logging.log4j.core.config.plugins.AppendersPlugin for element appenders with params(appenders= {Console, WroxFileAppender} ) 2013-05-09 07:26:03,356 DEBUG Generated plugins in 0.000026800 seconds 2013-05-09 07:26:03,358 DEBUG Calling createAppenderRef on class org.apache.logging.log4j.core.config.AppenderRef for element appender-ref with params(ref="Console", level="null", null) 2013-05-09 07:26:03,360 DEBUG Calling createAppenderRef on class org.apache.logging.log4j.core.config.AppenderRef for element appender-ref with params(ref="WroxFileAppender", level="null", null) 2013-05-09 07:26:03,362 DEBUG Calling createLogger on class org.apache.logging.log4j.core.config.LoggerConfig$RootLogger for element root with params(additivity="null", level="warn", includeLocation="null", appender-ref= {org.apache.logging.log4j.core.config.AppenderRef@39f14d85, org.apache.logging.log4j.core.config.AppenderRef@15fc1bda} , properties={}, Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null) 2013-05-09 07:26:03,364 DEBUG Calling createLogger on class org.apache.logging.log4j.core.config.LoggerConfig for element logger with params(additivity="null",level="info", name="com.wrox", includeLocation="null", appender-ref={}, properties={}, Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null) 2013-05-09 07:26:03,366 DEBUG Calling createLogger on class org.apache.logging.log4j.core.config.LoggerConfig for element logger with params(additivity="null",level="info", name="org.apache", includeLocation="null", appender-ref={}, properties={}, Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null) 2013-05-09 07:26:03,370 DEBUG Calling createLogger on class org.apache.logging.log4j.core.config.LoggerConfig for element logger with params(additivity="null",level="info", name="org.springframework", includeLocation="null", appender-ref={}, properties={}, Configuration(C:\Program Files\Apache Software Foundation\Tomcat 8.0\webapps\java\WEB-INF\classes\log4j2.xml), null) 2013-05-09 07:26:03,372 DEBUG Calling createLoggers on class org.apache.logging.log4j.core.config.plugins.LoggersPlugin for element loggers with params(loggers= {root, com.wrox, org.apache, org.springframework} ) 2013-05-09 07:26:03,375 DEBUG Reconfiguration completed
          Hide
          Nick Williams added a comment -

          Okay, I think I've narrowed it down. Two weeks ago I could log Throwables using beta5. Today I can't log Throwables using beta5. The only difference is my JVM has been upgraded from 1.8.0-ea-b86 to 1.8.0-ea-b88.

          It appears that Java 8 has changed something that makes this class not work. It will need to be updated to work with Java 8. I'm not sure exactly what that is. I'll examine the code some and see if I can't figure it out.

          Show
          Nick Williams added a comment - Okay, I think I've narrowed it down. Two weeks ago I could log Throwables using beta5. Today I can't log Throwables using beta5. The only difference is my JVM has been upgraded from 1.8.0-ea-b86 to 1.8.0-ea-b88. It appears that Java 8 has changed something that makes this class not work. It will need to be updated to work with Java 8. I'm not sure exactly what that is. I'll examine the code some and see if I can't figure it out.
          Hide
          Nick Williams added a comment -

          By the way, my JVM /does/ have a class sun.reflect.Reflection and that class /does/ have a public static method called getCallerClass. So I'm not sure how the stack is ever empty.

          Show
          Nick Williams added a comment - By the way, my JVM /does/ have a class sun.reflect.Reflection and that class /does/ have a public static method called getCallerClass. So I'm not sure how the stack is ever empty.
          Hide
          Remko Popma added a comment -

          Interesting.
          I originally thought that the Stack could only be empty if both the sun.reflect.Reflection class could not be loaded and PrivateSecurityManager could not be installed.

          However other reasons the Stack could end up empty (at least in theory) are:

          • Reflection.getCallerClass fails with an exception. This exception is currently ignored and not logged... The patch should probably address this too?
          • PrivateSecurityManager.getClasses returns an empty array.
          Show
          Remko Popma added a comment - Interesting. I originally thought that the Stack could only be empty if both the sun.reflect.Reflection class could not be loaded and PrivateSecurityManager could not be installed. However other reasons the Stack could end up empty (at least in theory) are: Reflection.getCallerClass fails with an exception. This exception is currently ignored and not logged... The patch should probably address this too? PrivateSecurityManager.getClasses returns an empty array.
          Hide
          Nick Williams added a comment -

          GOT IT!

          In Java <= 7, the signature of this method was:

          public static native java.lang.Class<?> getCallerClass(int realFramesToSkip)

          In Java 8 it has been changed to:

          public static native java.lang.Class<?> getCallerClass()

          (You can't skip frames anymore.)

          When ThrowableProxy tries to invoke getCallerClass(), it fails with a "wrong number of arguments" reflection exception. In the code, this exception is caught and ignored:

          try {
          final Object[] params = new Object[]

          {index}

          ;
          return (Class<?>) getCallerClass.invoke(null, params);
          } catch (final Exception ex)

          { // logger.debug("Unable to determine caller class via Sun Reflection", ex); }

          Never mind for a minute that ignoring this exception is bad, that's the root cause. This class will need to test the number of arguments getCallerClass takes, and either 1) not use it if it doesn't take exactly one argument or 2) use it differently. In either case, the stack should still be checked for emptiness. 1) Can be accomplished by changing this:

          if (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier)) {

          To this:

          if (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier) && method.getParameterTypes().length == 1 && method.getParameterTypes()[0] == int.class) {

          Show
          Nick Williams added a comment - GOT IT! In Java <= 7, the signature of this method was: public static native java.lang.Class<?> getCallerClass(int realFramesToSkip) In Java 8 it has been changed to: public static native java.lang.Class<?> getCallerClass() (You can't skip frames anymore.) When ThrowableProxy tries to invoke getCallerClass(), it fails with a "wrong number of arguments" reflection exception. In the code, this exception is caught and ignored: try { final Object[] params = new Object[] {index} ; return (Class<?>) getCallerClass.invoke(null, params); } catch (final Exception ex) { // logger.debug("Unable to determine caller class via Sun Reflection", ex); } Never mind for a minute that ignoring this exception is bad, that's the root cause. This class will need to test the number of arguments getCallerClass takes, and either 1) not use it if it doesn't take exactly one argument or 2) use it differently. In either case, the stack should still be checked for emptiness. 1) Can be accomplished by changing this: if (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier)) { To this: if (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier) && method.getParameterTypes().length == 1 && method.getParameterTypes() [0] == int.class) {
          Hide
          Nick Williams added a comment -

          Really, that whole looping-through-methods things is inefficient:

          final Method[] methods = clazz.getMethods();
          for (final Method method : methods) {

          It should just be this:

          getCallerClass = clazz.getMethod("getCallerClass", int.class);

          And then catch the exceptions (meaning method doesn't exist). If we want to try using the new Java 8 version of getCallerClass, in the catch we could then do this:

          getCallerClass = clazz.getMethod("getCallerClass");

          And further catch the exceptions (meaning that method doesn't exist, either). This would be way more efficient (and less fragile) than looping over methods...

          Show
          Nick Williams added a comment - Really, that whole looping-through-methods things is inefficient: final Method[] methods = clazz.getMethods(); for (final Method method : methods) { It should just be this: getCallerClass = clazz.getMethod("getCallerClass", int.class); And then catch the exceptions (meaning method doesn't exist). If we want to try using the new Java 8 version of getCallerClass, in the catch we could then do this: getCallerClass = clazz.getMethod("getCallerClass"); And further catch the exceptions (meaning that method doesn't exist, either). This would be way more efficient (and less fragile) than looping over methods...
          Hide
          Gary Gregory added a comment -

          Why are we using reflection in the first place?

          Show
          Gary Gregory added a comment - Why are we using reflection in the first place?
          Hide
          Nick Williams added a comment - - edited

          I think the more pertinent question is, why are we using sun.* classes in the first place?

          Classes in sun.* are not guaranteed to be in every JVM. In fact, they will NOT be in certain JVMs like Azul Systems' JVM. As such, you're not supposed to write code against sun.* classes.

          I assume that, in this case, we're using this class because it offers some performance benefit over getting stack information a supported way. I don't necessarily disagree with that, if that's the case. Performance benefits are definitely good and sometimes warrant doing something like this, as long as there's a backup in case the class doesn't exist. sun.reflect.Reflection seems to have been a relatively stable, universal class over the past 4 or 5 versions, until Java 8.

          If we DO continue to use this class because it creates a performance benefit, we HAVE to use reflection if we don't want to get a NoClassDefFoundError on non-supported JVMs.

          Show
          Nick Williams added a comment - - edited I think the more pertinent question is, why are we using sun.* classes in the first place? Classes in sun.* are not guaranteed to be in every JVM. In fact, they will NOT be in certain JVMs like Azul Systems' JVM. As such, you're not supposed to write code against sun.* classes. I assume that, in this case, we're using this class because it offers some performance benefit over getting stack information a supported way. I don't necessarily disagree with that, if that's the case. Performance benefits are definitely good and sometimes warrant doing something like this, as long as there's a backup in case the class doesn't exist. sun.reflect.Reflection seems to have been a relatively stable, universal class over the past 4 or 5 versions, until Java 8. If we DO continue to use this class because it creates a performance benefit, we HAVE to use reflection if we don't want to get a NoClassDefFoundError on non-supported JVMs.
          Hide
          Ralph Goers added a comment -

          The performance benefit of using this class is at least an order of magnitude. I did lots of testing which is why it uses the Reflection class first if it can, then the SecurityManager.

          Show
          Ralph Goers added a comment - The performance benefit of using this class is at least an order of magnitude. I did lots of testing which is why it uses the Reflection class first if it can, then the SecurityManager.
          Hide
          Remko Popma added a comment - - edited

          I was going to commit a change (like the patch above) to add defensive code that checks if the Stack is empty,
          but this would hide the root cause that the Reflection.getCallerClass method signature has changed.
          (And it would hide other potential issues as well.)

          I guess we should fix the Reflection.getCallerClass code so that it works with both Java8 and older.
          Then after that, what to do with empty Stacks?
          Add defensive code to prevent EmptyStackExceptions, or check at the top of the method and throw an (IllegalArgument, IllegalState or other) exception if the stack is empty?

          Show
          Remko Popma added a comment - - edited I was going to commit a change (like the patch above) to add defensive code that checks if the Stack is empty, but this would hide the root cause that the Reflection.getCallerClass method signature has changed. (And it would hide other potential issues as well.) I guess we should fix the Reflection.getCallerClass code so that it works with both Java8 and older. Then after that, what to do with empty Stacks? Add defensive code to prevent EmptyStackExceptions, or check at the top of the method and throw an (IllegalArgument, IllegalState or other) exception if the stack is empty?
          Hide
          Nick Williams added a comment -

          You can view the change made to the getCallerClass method here: http://hg.openjdk.java.net/jdk8/jdk8/jdk/rev/da6addef956e.

          The way it works was completely changed. It maybe shouldn't even have the same name. Everywhere this method was used in the JVM was calling it a single time with a constant value passed to it (and almost all of those values were 3), which is different from how we're using it (in a loop, incrementing the depth). They added a @sun.reflect.CallerSensitive annotation and changed getCallerClass to keep going back up the stack until it found a method without that annotation, so the depth parameter was no longer needed. They furthermore changed the native code so that there is no replacement for what we were doing.

          I'm going to add an enhancement request on the JDK project to create a replacement for it. It probably won't get accepted, but we'll see. For now, this class needs to get changed to:

          1) Not use getCallerClass unless (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier) && method.getParameterTypes().length == 1 && method.getParameterTypes()[0] == int.class)

          2) Use isEmpty() before peek() and add change (className.equals(clazz.getName())) to (clazz != null && className.equals(clazz.getName())).

          Show
          Nick Williams added a comment - You can view the change made to the getCallerClass method here: http://hg.openjdk.java.net/jdk8/jdk8/jdk/rev/da6addef956e . The way it works was completely changed. It maybe shouldn't even have the same name. Everywhere this method was used in the JVM was calling it a single time with a constant value passed to it (and almost all of those values were 3), which is different from how we're using it (in a loop, incrementing the depth). They added a @sun.reflect.CallerSensitive annotation and changed getCallerClass to keep going back up the stack until it found a method without that annotation, so the depth parameter was no longer needed. They furthermore changed the native code so that there is no replacement for what we were doing. I'm going to add an enhancement request on the JDK project to create a replacement for it. It probably won't get accepted, but we'll see. For now, this class needs to get changed to: 1) Not use getCallerClass unless (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier) && method.getParameterTypes().length == 1 && method.getParameterTypes() [0] == int.class) 2) Use isEmpty() before peek() and add change (className.equals(clazz.getName())) to (clazz != null && className.equals(clazz.getName())).
          Hide
          Gary Gregory added a comment -

          FWIW: sun.* classes will not work on IBM JVMs too.

          Show
          Gary Gregory added a comment - FWIW: sun.* classes will not work on IBM JVMs too.
          Hide
          Nick Williams added a comment -

          Just so I understand (which will help me file the enhancement request), what are we doing with this stack? It's not completely clear to me.

          Show
          Nick Williams added a comment - Just so I understand (which will help me file the enhancement request), what are we doing with this stack? It's not completely clear to me.
          Hide
          Remko Popma added a comment -

          Same question as Nick...
          Will the #resolvePackageData method still work correctly if the Stack is empty (after we add defensive code to prevent the EmptyStackException)?
          I don't understand the code well enough to answer that question.

          Show
          Remko Popma added a comment - Same question as Nick... Will the #resolvePackageData method still work correctly if the Stack is empty (after we add defensive code to prevent the EmptyStackException)? I don't understand the code well enough to answer that question.
          Hide
          Nick Williams added a comment -

          Yea, I don't understand what extra information we're getting that Thread#getStackTrace() / Throwable#getStackTrace() doesn't provide. This doesn't appear to be a substitute for *#getStackTrace(), since we're using both that AND the getCallerClass method.

          Show
          Nick Williams added a comment - Yea, I don't understand what extra information we're getting that Thread#getStackTrace() / Throwable#getStackTrace() doesn't provide. This doesn't appear to be a substitute for *#getStackTrace(), since we're using both that AND the getCallerClass method.
          Hide
          Nick Williams added a comment - - edited

          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

          Show
          Nick Williams added a comment - - edited 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
          Hide
          Ralph Goers added a comment -

          "whoever wrote it" is me. Yes, your understanding seems correct. This is to emulate the extended stack trace Logback provides. It is actually quite handy to have this information when it is available. As I recall, getCallerClass skips certain classes, so I believe the code was written to understand that. I don't recall them being in different orders - just that one returns the full stack and the other doesn't. So the code synchs them up after it finds a gap.

          I'll have to look at the code above to figure out if it is OK.

          Show
          Ralph Goers added a comment - "whoever wrote it" is me. Yes, your understanding seems correct. This is to emulate the extended stack trace Logback provides. It is actually quite handy to have this information when it is available. As I recall, getCallerClass skips certain classes, so I believe the code was written to understand that. I don't recall them being in different orders - just that one returns the full stack and the other doesn't. So the code synchs them up after it finds a gap. I'll have to look at the code above to figure out if it is OK.
          Hide
          Gary Gregory added a comment -

          Tangent: What about making those "last two bits" optional? You'd have to ask for them in your layout to get them.

          Show
          Gary Gregory added a comment - Tangent: What about making those "last two bits" optional? You'd have to ask for them in your layout to get them.
          Hide
          Nick Williams added a comment -

          Re Gary's suggestion: I tend to agree with this.

          Ralph, don't bother checking my code, it is not okay. I did some bench marking and it did not perform nearly as well as your original code. Measure is nanoseconds per iteration over 100,000 iterations.

          Original code, using replace/indexOf:
          no trailing slash: ~1000 nanoseconds
          trailing slash: ~1100 nanosoconds

          My code, exactly as above:
          no trailing slash: ~5500 nanoseconds
          trailing slash: ~6500 nanoseconds

          Modified version of my code, compiling regex first:
          no trailing slash: ~3200 nanoseconds
          trailing slash: ~3400 nanoseconds

          Show
          Nick Williams added a comment - Re Gary's suggestion: I tend to agree with this. Ralph, don't bother checking my code, it is not okay. I did some bench marking and it did not perform nearly as well as your original code. Measure is nanoseconds per iteration over 100,000 iterations. Original code, using replace/indexOf: no trailing slash: ~1000 nanoseconds trailing slash: ~1100 nanosoconds My code, exactly as above: no trailing slash: ~5500 nanoseconds trailing slash: ~6500 nanoseconds Modified version of my code, compiling regex first: no trailing slash: ~3200 nanoseconds trailing slash: ~3400 nanoseconds
          Hide
          Ralph Goers added a comment -

          I'll see if I can look into this in the next few days and see what can be done to support Java 8. To be honest, I've not even downloaded it yet.

          Show
          Ralph Goers added a comment - I'll see if I can look into this in the next few days and see what can be done to support Java 8. To be honest, I've not even downloaded it yet.
          Hide
          Nick Williams added a comment -

          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?

          Show
          Nick Williams added a comment - 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?
          Hide
          Remko Popma added a comment -

          I created LOG4J2-250 to separate the performance concerns of ThrowableProxy from the original issue (the EmptyStackException).

          Show
          Remko Popma added a comment - I created LOG4J2-250 to separate the performance concerns of ThrowableProxy from the original issue (the EmptyStackException).
          Hide
          Remko Popma added a comment -

          With regards to what would be the correct defensive code if the Stack is empty (for any reason):

          Does the above analysis mean that the #resolvePackageData method will not work properly if the Stack is empty (even if we prevent EmptyStackExceptions)?
          If that is the case, perhaps we should check at the top of the #resolvePackageData method and return an empty StackTracePackageElement[] if the Stack is empty.

          Show
          Remko Popma added a comment - With regards to what would be the correct defensive code if the Stack is empty (for any reason): Does the above analysis mean that the #resolvePackageData method will not work properly if the Stack is empty (even if we prevent EmptyStackExceptions)? If that is the case, perhaps we should check at the top of the #resolvePackageData method and return an empty StackTracePackageElement[] if the Stack is empty.
          Hide
          Nick Williams added a comment -

          No. If the stack is empty, it will get this information the slower way (Class.forName). If you return an empty array here, the whole class will stop working altogether. The original plan (stack.isEmpty() before stack.peek(), clazz != null && ...) is still the correct fix.

          Show
          Nick Williams added a comment - No. If the stack is empty, it will get this information the slower way (Class.forName). If you return an empty array here, the whole class will stop working altogether. The original plan (stack.isEmpty() before stack.peek(), clazz != null && ...) is still the correct fix.
          Hide
          Remko Popma added a comment -

          Updated Title, Environment and Description of this JIRA ticket to make it easier to find for other users encountering the same problem.

          Show
          Remko Popma added a comment - Updated Title, Environment and Description of this JIRA ticket to make it easier to find for other users encountering the same problem.
          Hide
          Ralph Goers added a comment -

          I have prevented the EmptyStack exception in revision 1481671. I also added a check for a single parameter to getCallerClass so it will not be found in Java 8. I have not found an equivalent replacement in Java 8 yet.

          Show
          Ralph Goers added a comment - I have prevented the EmptyStack exception in revision 1481671. I also added a check for a single parameter to getCallerClass so it will not be found in Java 8. I have not found an equivalent replacement in Java 8 yet.
          Hide
          Nick Williams added a comment -

          I verified that the revision stops the EmptyStackException in Java 8. In theory this issue can be closed, unless you want to leave it open as a reminder to look for Java 8 alternatives to getCallerClass at a later date.

          Show
          Nick Williams added a comment - I verified that the revision stops the EmptyStackException in Java 8. In theory this issue can be closed, unless you want to leave it open as a reminder to look for Java 8 alternatives to getCallerClass at a later date.
          Hide
          Max Larson added a comment -

          I have the same problem under a different environment. I'm using a Mac with JDK 1.7.0_45 (Oracle), which shows the same behavior as describe here, except that the issue still exist in the 2.0-beta9.

          Some background information we used Java 6 and log4j 2.0-beta4 and migrated over to Java 7 and stumbled over this issue. After reading through all the related information about this issues, we updated log4j to 2.0-beat9. Still the issue is existent. I cannot say for sure if it is the same cause as described here, but as long i can judge i would yes. That's why i comment here and doesn't open a new issue. BTW using again Java 6 doesn't expose this behavior.

          Show
          Max Larson added a comment - I have the same problem under a different environment. I'm using a Mac with JDK 1.7.0_45 (Oracle), which shows the same behavior as describe here, except that the issue still exist in the 2.0-beta9. Some background information we used Java 6 and log4j 2.0-beta4 and migrated over to Java 7 and stumbled over this issue. After reading through all the related information about this issues, we updated log4j to 2.0-beat9. Still the issue is existent. I cannot say for sure if it is the same cause as described here, but as long i can judge i would yes. That's why i comment here and doesn't open a new issue. BTW using again Java 6 doesn't expose this behavior.
          Hide
          Nick Williams added a comment -

          Max, I cannot replicate this in Java 1.7.0_45 or Java 8 on my Mac. Are you sure that you have deleted ALL beta4 JARs and replaced them with beta9 JARs?

          Show
          Nick Williams added a comment - Max, I cannot replicate this in Java 1.7.0_45 or Java 8 on my Mac. Are you sure that you have deleted ALL beta4 JARs and replaced them with beta9 JARs?
          Hide
          Max Larson added a comment -

          Nick, your right. After a long time searching, we found that a deprecated library developed by use put a beta4 jar on the release class path. Nevertheless until we found that, we could even reproduced it under Linux.
          Thanks for your effort, and sorry for the false report.

          Show
          Max Larson added a comment - Nick, your right. After a long time searching, we found that a deprecated library developed by use put a beta4 jar on the release class path. Nevertheless until we found that, we could even reproduced it under Linux. Thanks for your effort, and sorry for the false report.

            People

            • Assignee:
              Unassigned
              Reporter:
              Nick Williams
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development