Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

AsyncContext completion attempt after AsyncListener.onError is called #5675

Open
wendigo opened this issue Jun 11, 2024 · 15 comments
Open

AsyncContext completion attempt after AsyncListener.onError is called #5675

wendigo opened this issue Jun 11, 2024 · 15 comments

Comments

@wendigo
Copy link

wendigo commented Jun 11, 2024

We've observer an issue with Jersey 3.1.+ running in the Jetty EE10 container that applies to HTTP/2 protocol.

When client disconnects in the middle of the request (due to a timeout or whatever), it sends a RST_STREAM frame that on the server side, finishes an AsyncContext with an error through the AsyncListener.onError. It seems that Jersey doesn't understand this condition, and still tries to finish an AsyncContext when the AsyncResponse.complete is called. Since Jetty recycles request/response objects on AsyncContext error, there is no response to write output to, and the jersey code generates a non-actionable warning.

We've work around this issue by implementing trinodb/trino#22315 that seems to do a trick. I'd like to see a permanent solution on the Jersey side instead.

@wendigo
Copy link
Author

wendigo commented Jun 11, 2024

@lorban anything else to add here?

@lorban
Copy link

lorban commented Jun 11, 2024

@wendigo no; you accurately described the problem.

@jansupol
Copy link
Contributor

It looks like creating the test case is the most difficult part here

@wendigo
Copy link
Author

wendigo commented Aug 6, 2024

@jansupol is there a plan to fix this issue?

@jansupol
Copy link
Contributor

jansupol commented Aug 7, 2024

Yes, we plan to check on the possibilities for this.

@jbescos
Copy link
Member

jbescos commented Oct 1, 2024

I don't know about this part but I would like to take a look.

My understanding is that the issue is happening in the server side. The server receives cancel_stream_error and in this case, the server should close the connection. From what you say, Jersey is invoking #onError and later it invokes #complete. The fix is about not invoking #complete. Am I right?.

Are you able to print the stacktrace when #onError is invoked?.

@wendigo
Copy link
Author

wendigo commented Oct 1, 2024

Actually async context can complete with error on a different thread than the competing thread that will try to complete with a result. It seems that this isn't synchronized in any way.

@wendigo
Copy link
Author

wendigo commented Oct 1, 2024

In Jetty it's pretty visible because when the context is completed (successfully or not) the resources are recycled which causes errors to be logged (request/response doesn't exist)

@joakime
Copy link
Member

joakime commented Oct 16, 2024

Are you able to print the stacktrace when #onError is invoked?.

Here you go, this is the stacktrace received by AsyncContext.onError(Throwable).

In this case, the EOF results in a completed (and set to committed) response (if not completed yet).
By the time jersey interacts with this HttpServletResponse, it has been rendered useless, there is nothing jersey can do at this point. The user-agent / client is gone, the HTTP/2 stream is also gone. It is the equivalent of an HTTP/1.x client initiated disconnect (but far more reliable, as the disconnect is part of the on-network protocol)

	org.eclipse.jetty.io.EofException
		at org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2.onFailure(HttpStreamOverHTTP2.java:593)
		at org.eclipse.jetty.http2.server.internal.HTTP2ServerConnection.onStreamFailure(HTTP2ServerConnection.java:204)
		at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onFailure(HTTP2ServerConnectionFactory.java:173)
		at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onReset(HTTP2ServerConnectionFactory.java:160)
		at org.eclipse.jetty.http2.HTTP2Stream.notifyReset(HTTP2Stream.java:876)
		at org.eclipse.jetty.http2.HTTP2Stream.onReset(HTTP2Stream.java:586)
		at org.eclipse.jetty.http2.HTTP2Stream.process(HTTP2Stream.java:357)
		at org.eclipse.jetty.http2.HTTP2Session.onReset(HTTP2Session.java:345)
		at org.eclipse.jetty.http2.HTTP2Connection.onReset(HTTP2Connection.java:258)
		at org.eclipse.jetty.http2.parser.BodyParser.notifyReset(BodyParser.java:139)
		at org.eclipse.jetty.http2.parser.ResetBodyParser.onReset(ResetBodyParser.java:94)
		at org.eclipse.jetty.http2.parser.ResetBodyParser.parse(ResetBodyParser.java:61)
		at org.eclipse.jetty.http2.parser.Parser.parseBody(Parser.java:229)
		at org.eclipse.jetty.http2.parser.Parser.parse(Parser.java:156)
		at org.eclipse.jetty.http2.parser.ServerParser.parse(ServerParser.java:121)
		at org.eclipse.jetty.http2.HTTP2Connection$HTTP2Producer.produce(HTTP2Connection.java:342)
		at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produceTask(AdaptiveExecutionStrategy.java:512)
		at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:258)
		at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:195)
		at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:210)
		at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:157)
		at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:442)
		at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
		at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
		at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
		at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
		at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
		at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
		at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
		at org.eclipse.jetty.util.thread.MonitoredQueuedThreadPool$1.run(MonitoredQueuedThreadPool.java:73)
		at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
		at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
		at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
		at java.base/java.lang.Thread.run(Thread.java:1575)
	Caused by: java.io.EOFException: Reset cancel_stream_error
		at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onReset(HTTP2ServerConnectionFactory.java:159)
		... 30 more

@joakime
Copy link
Member

joakime commented Oct 16, 2024

Also note that Jersey works with the behaviors of the Servlet spec.

That means the HttpServletRequest / HttpServletResponse objects can be reused / recycled for other requests / responses.
That's built into the spec. If you hang onto the HttpServletRequest / HttpServletResponse too long after they have been completed, you could be working with a different request / response for an entirely different request.

@jbescos
Copy link
Member

jbescos commented Oct 17, 2024

I am reproducing it in jersey/connectors/jetty-http2-connector/src/test/java/org/glassfish/jersey/jetty/http2/connector/TimeoutTest#testTimeoutInRequest. These are 2 relevant stacktraces after the reset:

org.glassfish.jersey.server.internal.process.MappableException: org.eclipse.jetty.io.EofException: reset
	at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:67)
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139)
	at org.glassfish.jersey.logging.LoggingInterceptor.aroundWriteTo(LoggingInterceptor.java:244)
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139)
	at org.glassfish.jersey.message.internal.MessageBodyFactory.writeTo(MessageBodyFactory.java:1116)
	at org.glassfish.jersey.server.ServerRuntime$Responder.writeResponse(ServerRuntime.java:649)
	at org.glassfish.jersey.server.ServerRuntime$Responder.processResponse(ServerRuntime.java:380)
	at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:370)
	at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:259)
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248)
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:292)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:274)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:244)
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265)
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:235)
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:684)
	at org.glassfish.jersey.jetty.JettyHttpContainer.handle(JettyHttpContainer.java:176)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.Server.handle(Server.java:516)
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479)
	at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:439)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:137)
	at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:193)
	at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:148)
	at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:371)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:137)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
	at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: org.eclipse.jetty.io.EofException: reset
	at org.eclipse.jetty.http2.HTTP2Stream.onReset(HTTP2Stream.java:404)
	at org.eclipse.jetty.http2.HTTP2Stream.process(HTTP2Stream.java:320)
	at org.eclipse.jetty.http2.HTTP2Session.onReset(HTTP2Session.java:345)
	at org.eclipse.jetty.http2.parser.Parser$Listener$Wrapper.onReset(Parser.java:408)
	at org.eclipse.jetty.http2.parser.BodyParser.notifyReset(BodyParser.java:144)
	at org.eclipse.jetty.http2.parser.ResetBodyParser.onReset(ResetBodyParser.java:99)
	at org.eclipse.jetty.http2.parser.ResetBodyParser.parse(ResetBodyParser.java:66)
	at org.eclipse.jetty.http2.parser.Parser.parseBody(Parser.java:222)
	at org.eclipse.jetty.http2.parser.Parser.parse(Parser.java:151)
	at org.eclipse.jetty.http2.parser.ServerParser.parse(ServerParser.java:130)
	at org.eclipse.jetty.http2.HTTP2Connection$HTTP2Producer.produce(HTTP2Connection.java:271)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:362)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:186)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:137)
	at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:193)
	at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:148)
	at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:371)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
	... 3 more
 
Thread [jetty-http-server-1] (Suspended (breakpoint at line 815 in org.glassfish.jersey.server.ServerRuntime$AsyncResponder))	
	org.glassfish.jersey.server.ServerRuntime$AsyncResponder.onComplete(java.lang.Throwable) line: 815	
	org.glassfish.jersey.server.ServerRuntime$CompletionCallbackRunner$1.invoke(javax.ws.rs.container.CompletionCallback) line: 1165	
	org.glassfish.jersey.server.ServerRuntime$CompletionCallbackRunner$1.invoke(java.lang.Object) line: 1162	
	org.glassfish.jersey.server.ServerRuntime$CompletionCallbackRunner(org.glassfish.jersey.server.ServerRuntime$AbstractCallbackRunner<T>).executeCallbacks(org.glassfish.jersey.internal.util.Closure<T>) line: 1138	
	org.glassfish.jersey.server.ServerRuntime$CompletionCallbackRunner.onComplete(java.lang.Throwable) line: 1162	
	org.glassfish.jersey.server.ServerRuntime$Responder.processResponse(org.glassfish.jersey.server.ContainerResponse) line: 384	
	org.glassfish.jersey.server.ServerRuntime$Responder.process(org.glassfish.jersey.server.ContainerResponse) line: 370	
	org.glassfish.jersey.server.ServerRuntime$1.run() line: 259	
	org.glassfish.jersey.internal.Errors$1.call() line: 248	
	org.glassfish.jersey.internal.Errors$1.call() line: 244	
	org.glassfish.jersey.internal.Errors.process(java.util.concurrent.Callable<T>, boolean) line: 292	
	org.glassfish.jersey.internal.Errors.process(org.glassfish.jersey.internal.util.Producer<T>, boolean) line: 274	
	org.glassfish.jersey.internal.Errors.process(java.lang.Runnable) line: 244	
	org.glassfish.jersey.inject.hk2.Hk2RequestScope(org.glassfish.jersey.process.internal.RequestScope).runInScope(org.glassfish.jersey.process.internal.RequestContext, java.lang.Runnable) line: 265	
	org.glassfish.jersey.server.ServerRuntime.process(org.glassfish.jersey.server.ContainerRequest) line: 235	
	org.glassfish.jersey.server.ApplicationHandler.handle(org.glassfish.jersey.server.ContainerRequest) line: 684	
	org.glassfish.jersey.jetty.JettyHttpContainer.handle(java.lang.String, org.eclipse.jetty.server.Request, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) line: 176	
	org.eclipse.jetty.server.Server(org.eclipse.jetty.server.handler.HandlerWrapper).handle(java.lang.String, org.eclipse.jetty.server.Request, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) line: 127	
	org.eclipse.jetty.server.Server.handle(org.eclipse.jetty.server.HttpChannel) line: 516	
	org.eclipse.jetty.http2.server.HTTP2ServerConnection$ServerHttpChannelOverHTTP2(org.eclipse.jetty.server.HttpChannel).lambda$handle$1() line: 487	
	org.eclipse.jetty.server.HttpChannel$$Lambda.0x00007fa29c397a10.dispatch() line: not available	
	org.eclipse.jetty.http2.server.HTTP2ServerConnection$ServerHttpChannelOverHTTP2(org.eclipse.jetty.server.HttpChannel).dispatch(javax.servlet.DispatcherType, org.eclipse.jetty.server.HttpChannel$Dispatchable) line: 732	
	org.eclipse.jetty.http2.server.HTTP2ServerConnection$ServerHttpChannelOverHTTP2(org.eclipse.jetty.server.HttpChannel).handle() line: 479	
	org.eclipse.jetty.http2.server.HTTP2ServerConnection$ServerHttpChannelOverHTTP2(org.eclipse.jetty.server.HttpChannel).run() line: 439	
	org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(java.lang.Runnable) line: 338	
	org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(boolean) line: 315	
	org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(boolean) line: 173	
	org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce() line: 137	
	org.eclipse.jetty.http2.server.HTTP2ServerConnection(org.eclipse.jetty.http2.HTTP2Connection).produce() line: 193	
	org.eclipse.jetty.http2.server.HTTP2ServerConnection(org.eclipse.jetty.http2.HTTP2Connection).onFillable() line: 148	
	org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded() line: 371	
	org.eclipse.jetty.io.AbstractEndPoint$1(org.eclipse.jetty.io.FillInterest).fillable() line: 105	
	org.eclipse.jetty.io.ChannelEndPoint$1.run() line: 104	
	org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(java.lang.Runnable) line: 338	
	org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(boolean) line: 315	
	org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(boolean) line: 173	
	org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce() line: 137	
	org.eclipse.jetty.io.ManagedSelector$$Lambda.0x00007fa29c2b0b98.run() line: not available	
	org.glassfish.jersey.jetty.JettyHttpContainerFactory$JettyConnectorThreadPool(org.eclipse.jetty.util.thread.QueuedThreadPool).runJob(java.lang.Runnable) line: 883	
	org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run() line: 1034	
	java.lang.Thread.runWith(java.lang.Object, java.lang.Runnable) line: 1596	
	java.lang.Thread.run() line: 1583	

@jbescos
Copy link
Member

jbescos commented Oct 18, 2024

I found that the exception was not re-throw because the response was already committed. I have modified the code, so if the exception is instance of IOException, we still throw it up so the container can do something.

Now the exception reaches the Jetty container (as you can see in the next screenshoot) but I am having questions about whether it is going to reuse request/response objects or not. Maybe you can help me with this verification, I will write instructions soon.

image

jbescos added a commit to jbescos/jersey that referenced this issue Oct 18, 2024
…clipse-ee4j#5675

Signed-off-by: Jorge Bescos Gascon <jorge.bescos.gascon@oracle.com>
@jbescos
Copy link
Member

jbescos commented Oct 18, 2024

@wendigo could you help me to verify the fix?. Although I am trying to help, I am not expert in this area. Could you overwrite the class inside the zip under jersey-server.jar:classes/org/glassfish/jersey/server/ServerRuntime.class and try again?. Now the exception will reach Jetty container and I hope it will be able deal with it.
overwrite.zip

@jbescos
Copy link
Member

jbescos commented Oct 22, 2024

Hi Jetty experts!, did any of you have a chance to verify the fix?.

@wendigo
Copy link
Author

wendigo commented Oct 22, 2024

@jbescos it doesn't change much in our case. I've written some explanation here: #5776

jbescos added a commit to jbescos/jersey that referenced this issue Oct 29, 2024
…clipse-ee4j#5675

Signed-off-by: Jorge Bescos Gascon <jorge.bescos.gascon@oracle.com>
jbescos added a commit to jbescos/jersey that referenced this issue Oct 29, 2024
…clipse-ee4j#5675

Signed-off-by: Jorge Bescos Gascon <jorge.bescos.gascon@oracle.com>
jbescos added a commit to jbescos/jersey that referenced this issue Oct 30, 2024
…clipse-ee4j#5675

Signed-off-by: Jorge Bescos Gascon <jorge.bescos.gascon@oracle.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants