12

A couple days ago, I got a support ticket for this NullPointerException:

com.google.gwt.user.server.rpc.UnexpectedException: Service method 'public abstract com.redacted.SalesResponsePagination com.redacted.StatisticsService.findSalesData(com.redacted.ConfStats) throws com.redacted.AsyncException' threw an unexpected exception: java.lang.NullPointerException
    at com.google.gwt.user.server.rpc.RPC.encodeResponseForFailure(RPC.java:389)
    at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:579)
    at ... (typical GWT + Tomcat stacktrace)
Caused by: java.lang.NullPointerException
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
    at java.lang.reflect.Constructor.newInstance(Unknown Source)
    at java.util.concurrent.ForkJoinTask.getThrowableException(Unknown Source)
    at java.util.concurrent.ForkJoinTask.reportException(Unknown Source)
    at java.util.concurrent.ForkJoinTask.invoke(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp.evaluateParallel(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateParallel(Unknown Source)
    at java.util.stream.AbstractPipeline.evaluate(Unknown Source)
    at java.util.stream.ReferencePipeline.forEach(Unknown Source)
    at com.redacted.StatisticsControllerImpl.replacePrices(StatisticsControllerImpl.java:310)
    at com.redacted.StatisticsControllerImpl.findSalesData(StatisticsControllerImpl.java:288)
    at com.redacted.StatisticsServiceImpl.findSalesData(StatisticsServiceImpl.java:83)
    at sun.reflect.GeneratedMethodAccessor752.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Unknown Source)
    at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:561)
    ... 33 more
Caused by: java.lang.NullPointerException
    at com.redacted.StatisticsControllerImpl.lambda$replacePrices$27(StatisticsControllerImpl.java:317)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(Unknown Source)
    at ... (typical stream.forEach stacktrace)

Now, this was an easy one because the exact line number for the NPE was in plain sight; all I had to do was go to StatisticsControllerImpl.java:317:

    salesResponsePagination.getSalesResponses().parallelStream()
            .peek(sr -> /*...*/)
            .filter(sr -> /*...*/)
/*310*/     .forEach(sr -> {
                final List<CartElement> sentCEs = DaoService.getCartElementDAO().getSentCEs(/*...*/);
                if (sentCEs != null && !sentCEs.isEmpty() && sentCEs.get(0) != null) {
                    final CartElement ce = sentCEs.get(0);
                    // some more non-NPE lines...
/*317*/             if (sr.getCurrency().equals(ce.getPurchaseCurrency()) && sr.getPrice().equals(ce.getPurchasePrice().intValue()) && !ce.getCurrency().equals(ce.getPurchaseCurrency())) {
                        // Some currency exchanging
                    }
                    // Etcetera (about 12 lines more)
            });

And replace the .equals() calls with Object.equals() to avoid the NPE (investigating the reasons why some sales were registered with a NULL price or currency came later). Test, commit, push, send ticket to QA.

However, the next day QA returned the ticket saying that the NPE persisted, and they included a new, almost similar stack trace:

com.google.gwt.user.server.rpc.UnexpectedException: Service method 'public abstract com.redacted.SalesResponsePagination com.redacted.StatisticsService.findSalesData(com.redacted.ConfStats) throws com.redacted.AsyncException' threw an unexpected exception: java.lang.NullPointerException
    at com.google.gwt.user.server.rpc.RPC.encodeResponseForFailure(RPC.java:389)
    at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:579)
    at ... (typical GWT + Tomcat stacktrace)
Caused by: java.lang.NullPointerException
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
    at java.lang.reflect.Constructor.newInstance(Unknown Source)
    at java.util.concurrent.ForkJoinTask.getThrowableException(Unknown Source)
    at java.util.concurrent.ForkJoinTask.reportException(Unknown Source)
    at java.util.concurrent.ForkJoinTask.invoke(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp.evaluateParallel(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateParallel(Unknown Source)
    at java.util.stream.AbstractPipeline.evaluate(Unknown Source)
    at java.util.stream.ReferencePipeline.forEach(Unknown Source)
    at com.redacted.StatisticsControllerImpl.replacePrices(StatisticsControllerImpl.java:310)
    at com.redacted.StatisticsControllerImpl.findSalesData(StatisticsControllerImpl.java:288)
    at com.redacted.StatisticsServiceImpl.findSalesData(StatisticsServiceImpl.java:83)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Unknown Source)
    at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:561)
    ... 33 more
Caused by: java.lang.NullPointerException

This stack trace was exactly the same as the previous one, except for two things:

  • This call was using NativeMethodAccessorImpl instead of GeneratedMethodAccessor752. Compare:
    at com.redacted.StatisticsServiceImpl.findSalesData(StatisticsServiceImpl.java:83)
    at sun.reflect.GeneratedMethodAccessor752.invoke(Unknown Source)
    vs
    at com.redacted.StatisticsServiceImpl.findSalesData(StatisticsServiceImpl.java:83)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

  • This one was missing the stack trace for the lambda. The line where the NPE happened was missing.

This threw me off initially. Why was the last part of the stack trace missing? I asked QA to re-test and re-attach the stack trace a couple times, until I got a complete one; however, the complete one I got in the end was based on GeneratedMethodAccesor once again.

Now, if I understand correctly, sun.reflect.NativeMethodAccessorImpl is used for the first invocations of a method, until JIT has enough info to generate an optimized accesor for that method in the form of sun.reflect.GeneratedMethodAccessorNNN.
What I don't understand is: if Native is using my code and Generated is using JIT's generated code, shouldn't Native show more info about my code, not less?

So my question is:
Why do lambda runtime exceptions thrown inside sun.reflect.NativeMethodAccessorImpl seem to be missing the lambda's stack trace?

Can this be a bug in JDK's source code? Especially when the very same exception thrown inside sun.reflect.GeneratedMethodAccessor includes the lambda stack trace without problem.


The following code manages to get a stack trace similar to the first one. I can force the use of NativeMethodAccessor or GeneratedMethodAccesor by running it with a sufficiently low or high first parameter, respectively (i.e. java test.Main 1 or java test.Main 30).
However, the lambda part of it is always present, whether using Native or Generated.

package test;

import java.lang.reflect.Method;
import java.util.stream.IntStream;

class MyOtherClass {
    public void methodWithLambda(boolean fail) {
        IntStream.range(0, 1000).parallel().forEach(k -> {
            if (fail && k % 500 == 0)
                throw new NullPointerException();
        });
    }
    public String methodProxy(boolean fail) {
        methodWithLambda(fail);
        return "OK";
    }
}

class MyClass {
    public String methodReflected(Boolean fail) {
        return new MyOtherClass().methodProxy(fail);
    }
}

class Main {
    public static void main(String[] args) throws Exception {
        Class<MyClass> clazz = MyClass.class;
        Object instance = clazz.newInstance();
        Method method = clazz.getMethod("methodReflected", Boolean.class);
        int reps = args.length >= 1 ? Integer.valueOf(args[0]) : 20; 
        for (; reps --> 0;) {
            // Several non-failing calls to force creation of GeneratedMethodAccesor
            System.out.println((String) method.invoke(instance, false));
        }
        // Failing call
        System.out.println((String) method.invoke(instance, true));
    }
}

Stack trace for the above code when using NativeMethodAccesor:

Exception in thread "main" java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at test.Main.main(Main.java:36)
Caused by: java.lang.NullPointerException
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
        at java.lang.reflect.Constructor.newInstance(Unknown Source)
        at java.util.concurrent.ForkJoinTask.getThrowableException(Unknown Source)
        at java.util.concurrent.ForkJoinTask.reportException(Unknown Source)
        at java.util.concurrent.ForkJoinTask.invoke(Unknown Source)
        at java.util.stream.ForEachOps$ForEachOp.evaluateParallel(Unknown Source)
        at java.util.stream.ForEachOps$ForEachOp$OfInt.evaluateParallel(Unknown Source)
        at java.util.stream.AbstractPipeline.evaluate(Unknown Source)
        at java.util.stream.IntPipeline.forEach(Unknown Source)
        at java.util.stream.IntPipeline$Head.forEach(Unknown Source)
        at test.MyOtherClass.methodWithLambda(Main.java:8)
        at test.MyOtherClass.methodProxy(Main.java:14)
        at test.MyClass.methodReflected(Main.java:21)
        ... 5 more
Caused by: java.lang.NullPointerException
        at test.MyOtherClass.lambda$methodWithLambda$0(Main.java:10)
        at java.util.stream.ForEachOps$ForEachOp$OfInt.accept(Unknown Source)
        at java.util.stream.Streams$RangeIntSpliterator.forEachRemaining(Unknown Source)
        at java.util.Spliterator$OfInt.forEachRemaining(Unknown Source)
        at java.util.stream.AbstractPipeline.copyInto(Unknown Source)
        at java.util.stream.ForEachOps$ForEachTask.compute(Unknown Source)
        at java.util.concurrent.CountedCompleter.exec(Unknown Source)
        at java.util.concurrent.ForkJoinTask.doExec(Unknown Source)
        at java.util.concurrent.ForkJoinPool$WorkQueue.execLocalTasks(Unknown Source)
        at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(Unknown Source)
        at java.util.concurrent.ForkJoinPool.runWorker(Unknown Source)
        at java.util.concurrent.ForkJoinWorkerThread.run(Unknown Source)

EDIT: Just to be clear: I am not looking for ways to fix this NPE, nor ways to force the lambda's stack trace to print. What I want to know is the reason why the above happens: different implementations? A bug? Something to do with forEach()?

Thiyagu
  • 17,362
  • 5
  • 42
  • 79
walen
  • 7,103
  • 2
  • 37
  • 58
  • By the way, are you sure that sr isn't null at any point? Streams may contain nulls, in which case sr.getCurrency(), sr.getPrice() etc will encounter an NPE. you could simply filter those out earlier in the stream if you don't need to address them. – Assafs Jan 21 '19 at 08:39
  • 1
    @Assafs Yes I am sure `sr` is not null, else it would've failed in `peek(sr -> ...)` or `filter(sr -> ...)` before the `forEach`. But my question is not about the NPE, it is about the reason why the stack trace differs depending on the accesor class used by the Reflection library. – walen Jan 21 '19 at 09:00
  • You can use lambda wrapper and provide your exception handling code with stacktrace statements which will print the stack trace of the exceptions. – Ripudaman Singh Jan 22 '19 at 14:01
  • @RipudamanSingh Thanks for your input. What I want to know is the reason why it is printed or not depending on the reflection accessor used. – walen Jan 24 '19 at 08:06
  • @walen if you provide a basic example on some repo describing this issue, it'd be great! – Jonathan JOhx Jan 25 '19 at 05:15
  • @JonathanJohx I've not yet been able to reproduce this with simpler code. I've managed to get a stack trace similar to the one shown, however in my tests the lambda's stack trace is visible in both the `Native` and the `Generated` versions :| – walen Jan 25 '19 at 09:26

1 Answers1

6

This might be an issue of JDK-6678999, “Stacktrace missing after null string comparisons”:

After comparing a string to null and catching the exception and repeating the operation, JVM starts throwing "stackless" NullPointerException (it occurs after 9000 loops but this is variable)

The evaluation of the issue is

When the server compiler compiles a method, the stack trace in an exception thrown by that method may be omitted for performance purposes.

[…] If the user always wants stack traces, use the -XX:-OmitStackTraceInFastThrow option to the VM.

So, the option -XX:-OmitStackTraceInFastThrow may solve the issue.

Note that the bug report was against Java 6, but since it has been closed as “Won't Fix”, it may still be relevant, though you would have to replace “server compiler” with “c2 compiler” in the explanation now.

The use of NativeMethodAccessorImpl or GeneratedMethodAccessor… is not relevant to this issue, except that both have a common cause; a higher number of executions may trigger the optimizations.

Holger
  • 285,553
  • 42
  • 434
  • 765
  • Thanks for chiming in! I'll try to adapt the test code with this new info in mind, and see if I can reproduce the behavior. – walen Jan 25 '19 at 11:16
  • 1
    Still cannot reproduce it. Your answer is the only thing I've seen remotely resembling a possible cause for this behavior, though, so I'm awarding the full bounty anyway. – walen Jan 28 '19 at 13:06