NullPointerException stack trace not available without debug agent

Question

I have recently found a bug that causes a NullPointerException. The exception is caught and logged using a standard slf4j statement. Abridged code below:

for(Action action : actions.getActions()) {
    try {
        context = action.execute(context);
    } catch (Exception e) {
        logger.error("...", e);
        break;
    }
}

As you can see, nothing fancy. However, of all the exception logging statements that we have, just this one does not print a stack trace. All it prints is the message (represented as "...") and the name of the exception class (java.lang.NullPointerException).

Since the stack trace on an exception is lazy loaded, I thought maybe there is a instruction reordering issue of some sort and decided to call e.getStackTrace() before the log statement. This made no difference.

So I decided to restart with the debug agent enabled. However, because I even attached to the process, I noticed that now the stack traces were printing. So clearly the presence of the debug agent caused some additional debug information to become available.

I have since then fixed the root cause of the exception. But I would like to learn why the stack trace was unavailable without a debugger. Anyone know?

Clarification: this is not a logging issue. Imagine the same try/catch clause, but in the catch, I print the value of:

e.getStackTrace().length

Without a debugger this prints '0', with a debugger it prints a positive number (9 in this case).

More info: this is happening on JDK 1.6.0_13, 64bit, amd64, linux 2.6.9

Peta

what vm are you using? that behaviour sounds very weird. – Obit

JDK 1.6.0_13, 64bit on linux 2.6.9 – Peta

What happens when you 'throw new NullPointerException()' yourself inside of the try? – Expropriate

Try to log the actions, so you can have an idea which action causes this – Casanova

I have already fixed the underlying issue. I would just like an explanation of this behaviour. – Peta

Thanks for this question (and the solution)! I just received this as a bug report for my logging application and was nearly going insane... because there was no bug in my code. This cleared things up quite a bit. – Helvetic

possible duplicate of NullPointerException in Java with no StackTrace – Psalmist

Answer 1

Is it possible that this code is in an inner loop? Then then JIT compiler might be compiling the call stack for this to native code, losing the stack information. Then when you attach the debugger it disables the JIT, making the information available again.

The other manual exceptions keep displaying the information as the JIT is not optimising.

It looks like this can sometimes happen for others from a comment in this class source code at line 102:

http://logging.apache.org/log4j/1.2/xref/org/apache/log4j/spi/LocationInfo.html

Atlantis

Later I managed to confirm that turning off the JIT (JAVA_COMPILER=false) causes the full stack trace to be available whenever this exception occurs. – Peta

Answer 2

With the JVM flag -XX:-OmitStackTraceInFastThrow you can disable the performance optimization of the JVM for this use case. IF this parameter is given, which disables the flag, the stacktrace will be available.

For more information please have a look at the following release notes:

"The compiler in the server VM now provides correct stack backtraces for all "cold" built-in exceptions. For performance purposes, when such an exception is thrown a few times, the method may be recompiled. After recompilation, the compiler may choose a faster tactic using preallocated exceptions that do not provide a stack trace. To disable completely the use of preallocated exceptions, use this new flag: -XX:-OmitStackTraceInFastThrow." http://java.sun.com/j2se/1.5.0/relnotes.html

Emersonemery

We had the same issue again and tried this option, and it worked really well, much better than turning off the JIT completely. Thanks! – Peta

Answer 3

I can replicate this but it seems kind of weird that this would be happening in your Action somewhere.

If you call setStackTrace with an empty array, that'll cause only the text to be shown.

 public class Fark {
   public static void main(String[] args) {
       try {
           Fark.throwMe(args.length != 0);

       }
       catch (Exception e) {
           e.printStackTrace();
       }

   }

     public static final void throwMe(boolean arg) throws Exception{
         Exception e = new NullPointerException();
         if (arg) {
           e.setStackTrace(new StackTraceElement[0]);
         }
         throw e;
     }
 }

Running it....

% java Fark
java.lang.NullPointerException
        at Fark.throwMe(Fark.java:15)
        at Fark.main(Fark.java:5)

% java Fark nothing
java.lang.NullPointerException

Expropriate

Yes, someone mentioned this as well. This is not the case. – Peta

Does the same thing happen if you just throw a NullPointerException yourself in the try? – Expropriate

Yes, same behavior if I throw manually myself. And this happens only in this try/catch. In others where I throw manually, I get normal (ie, full stack) behaviour. – Peta