Sometime, NullPointerException is reported in HttpChannelState$HandlerInvoker.completeStream

[yokotaso]

Jetty version(s)

12.0.7

Jetty Environment jetty12-only

Java version/vendor (use: java -version)

$ java -version
openjdk version "17.0.7" 2023-04-18 LTS
OpenJDK Runtime Environment Corretto-17.0.7.7.1 (build 17.0.7+7-LTS)
OpenJDK 64-Bit Server VM Corretto-17.0.7.7.1 (build 17.0.7+7-LTS, mixed mode, sharing)

OS type/version

$ cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=20.04
DISTRIB_CODENAME=focal
DISTRIB_DESCRIPTION="Ubuntu 20.04.6 LTS"

Description

Sometime, NullPointerException is reported in our production enviromnent.

Some of stacktraces are as like bellow:

java.lang.NullPointerException: Cannot invoke \"org.eclipse.jetty.server.HttpStream.succeeded()\" because \"stream\" is null\n
 at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.completeStream(HttpChannelState.java:724)\n
 at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.succeeded(HttpChannelState.java:675)\n
 at org.eclipse.jetty.util.thread.SerializedInvoker$Link.run(SerializedInvoker.java:191)\n
 at org.eclipse.jetty.util.thread.SerializedInvoker.run(SerializedInvoker.java:117)\n
 at org.eclipse.jetty.server.internal.HttpChannelState$ChannelResponse.succeeded(HttpChannelState.java:1271)\n
 at org.eclipse.jetty.server.internal.HttpConnection$SendCallback.onCompleteSuccess(HttpConnection.java:908)\n
 at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:333)\n
 at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:231)\n
 at org.eclipse.jetty.server.internal.HttpConnection$HttpStreamOverHTTP1.send(HttpConnection.java:1419)\n
 at org.eclipse.jetty.server.HttpStream$Wrapper.send(HttpStream.java:179)\n
 at org.eclipse.jetty.server.internal.HttpChannelState$ChannelCallback.succeeded(HttpChannelState.java:1501)\n
 at org.eclipse.jetty.util.Callback$Nested.succeeded(Callback.java:435)\n
 at org.eclipse.jetty.util.CountingCallback.succeeded(CountingCallback.java:63)\n

java.lang.NullPointerException: Cannot invoke \"org.eclipse.jetty.server.internal.HttpChannelState$ChannelRequest.getAttribute(String)\" because \"this.this$0._request\" is null\n
 at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.completeStream(HttpChannelState.java:712)\n
 at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.succeeded(HttpChannelState.java:675)\n
 at org.eclipse.jetty.util.thread.SerializedInvoker$Link.run(SerializedInvoker.java:191)\n
 at org.eclipse.jetty.util.thread.SerializedInvoker.run(SerializedInvoker.java:117)\n
 at org.eclipse.jetty.server.internal.HttpChannelState$ChannelResponse.succeeded(HttpChannelState.java:1271)\n
 at org.eclipse.jetty.server.internal.HttpConnection$SendCallback.onCompleteSuccess(HttpConnection.java:908)
 at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:333)
 at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:231)
 at org.eclipse.jetty.server.internal.HttpConnection$HttpStreamOverHTTP1.send(HttpConnection.java:1419)
 at org.eclipse.jetty.server.HttpStream$Wrapper.send(HttpStream.java:179)
 at org.eclipse.jetty.server.internal.HttpChannelState$ChannelCallback.succeeded(HttpChannelState.java:1501)
 at org.eclipse.jetty.util.Callback$Nested.succeeded(Callback.java:435)
 at org.eclipse.jetty.util.CountingCallback.succeeded(CountingCallback.java:63)

And there is case that jetty don't any stacktraces. error message is Serialized invocation error class which report this log is SerializedInvoker

java.lang.NullPointerException: null

How to reproduce? Sorry, I have no idea.

[lorban]

Sorry for the delay getting back to you.

I've had a close look at the NPE you reported and what could be causing it and there's nothing obvious. All I can say so far is that there seems to be some ordering or double execution issue in the cleanup of a request, as HttpChannelState$HandlerInvoker.succeeded() should be invoked only before HttpStream.succeeded() but in your case it's not.

Could you please try to collect more information about your environment to help us track down this problem? For instance:

• Did you report the whole stack trace or is there a cause you cut off?
• Do you have any idea what protocol is causing this issue? HTTP 1 or 2? WebSockets?
• Do you know of any related problem on the client side? Was that an aborted request, or a timed-out one?

Anything else that could help us understand the context of this stack trace would help.

Thanks!

[yokotaso]

Thank you for replying my issue.

Do you have any idea what protocol is causing this issue? HTTP 1 or 2? WebSockets? Did you report the whole stack trace or is there a cause you cut off?

I use HTTP1.1, Nginx proxy nginx server exists between client and jetty server.

Nginx config is like bellow

upstream nastyserver {
    server 127.0.0.1:8901; // Our jetty server works!
    keepalive 30;
}

some nginx outputs some error logs.

2024/04/23 08:09:42 [error] 160873#0: *1057844 upstream prematurely closed connection while reading response header from upstream, client: 10.177.72.132, server: , request: "POST (ommit) HTTP/1.1", upstream: 

when I turned off keepalive setting, stack trace of issue is not happend. So I think it might has something to do with idle connections.

Anything else that could help us understand the context of this stack trace would help.

Offcourse, I have been examinig problem, If I found cause of problem, I would write commend.

sincerely 👍

[lorban]

Jetty 12.0.9 has been released with some fixes related to similar issues. Could you please give it a shot? With a little luck, it will have your problem fixed.

Thanks!

[yokotaso]

@lorban Than you for informing new release. But, unfortunately I came across same stack trace. Anyway, I contine to survery this problem, and if I found cause of problem, I'll comment it.

Thank you 👍

[yokotaso]

@lorban I found how it reproduce. I write Callback#succeeded in CompletableFuture#onComplete . Perhaps CompletableFuture#onComplete might be called multiple times.

I modify code that Callback#succeeded would be called in CompletableFuture#supplyAsync. This problem doesn't happned.

As a conclusion, my code misunderstanding happened to this phenomenon.

[lorban]

So you mean you were calling Callback.succeeded() more than once? In that case, that's indeed your error and it could lead to such exception.

Thanks for the explanation!