Re: [jetty-users] incorrect http 200 response while shutting down jetty

["Robben, Bert" <Bert.Robben@xxxxxxxxxxxxx>]

I added a simple unit test now to https://github.com/eclipse/jetty.project/issues/8271 that shows the issue.

 

From: jetty-users <jetty-users-bounces@xxxxxxxxxxx> On Behalf Of Robben, Bert via jetty-users
Sent: Thursday, 7 July, 2022 4:42 PM
To: JETTY user mailing list <jetty-users@xxxxxxxxxxx>
Cc: Robben, Bert <Bert.Robben@xxxxxxxxxxxxx>
Subject: Re: [jetty-users] incorrect http 200 response while shutting down jetty

 

Done. See https://github.com/eclipse/jetty.project/issues/8271

 

From: jetty-users <jetty-users-bounces@xxxxxxxxxxx> On Behalf Of Joakim Erdfelt
Sent: Thursday, 7 July, 2022 3:49 PM
To: JETTY user mailing list <jetty-users@xxxxxxxxxxx>
Subject: Re: [jetty-users] incorrect http 200 response while shutting down jetty

 

This would make for a good issue to open.

Joakim Erdfelt / joakim@xxxxxxxxxxx

 

 

On Thu, Jul 7, 2022 at 8:46 AM Robben, Bert via jetty-users <jetty-users@xxxxxxxxxxx> wrote:

Hi,

 

We are using the graceful shutdown feature (in other words, we configured our Jetty server with the StatisticsHandler as advised in the aftermath of https://github.com/eclipse/jetty.project/issues/8210) and noticed that a small number of requests are now getting an incorrect HTTP 200 response. These requests enter the server just after we asked the server to stop (by calling Server#stop). The vast majority of requests that enter the server after we called stop are terminated with a proper 503. However, sometimes, one or two requests get this 200 response. The response is incorrect because it’s NOT delivered by our REST resources (they return HTTP 204, but never HTTP 200), and even worse, our server-side logic for this particular request was NOT executed. Before we started using StatisticsHandler we never got this.

 

I did some digging and managed to produce(*) a stack trace that shows that the response seems to be written because the statistics handler flushes the response buffer.

 

I think this issue is caused by a race condition where the server is not yet shut down in the beginning of StatisticsHandler.handle, but by the time execution reaches the end of this method, the server is shutting down.

 

at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:998)

at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:1086)

at org.eclipse.jetty.server.HttpOutput.channelWrite(HttpOutput.java:285)

at org.eclipse.jetty.server.HttpOutput.channelWrite(HttpOutput.java:269)

at org.eclipse.jetty.server.HttpOutput.flush(HttpOutput.java:751)

at org.eclipse.jetty.server.Response.flushBuffer(Response.java:1112)

at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:208)

at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234)

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.HttpConnection.onFillable(HttpConnection.java:277)

at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)

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)

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.lang.Thread.run(Thread.java:748)

 

Debug logs are attached for a problematic request/response.

 

We’re using Jetty 9.4.46.v20220331

 

Bert

 

(*) For clarity, no exceptions are thrown. I just dumped the current stack trace at that point.

The information contained in this message is proprietary and/or confidential. If you are not the intended recipient, please: (i) delete the message and all copies; (ii) do not disclose, distribute or use the message in any manner; and (iii) notify the sender immediately. In addition, please be aware that any message addressed to our domain is subject to archiving and review by persons other than the intended recipient. Thank you.

FIS Internal Use Only

_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To unsubscribe from this list, visit https://www.eclipse.org/mailman/listinfo/jetty-users

The information contained in this message is proprietary and/or confidential. If you are not the intended recipient, please: (i) delete the message and all copies; (ii) do not disclose, distribute or use the message in any manner; and (iii) notify the sender immediately. In addition, please be aware that any message addressed to our domain is subject to archiving and review by persons other than the intended recipient. Thank you.

FIS Internal Use Only

 

FIS Internal Use Only

The information contained in this message is proprietary and/or confidential. If you are not the intended recipient, please: (i) delete the message and all copies; (ii) do not disclose, distribute or use the message in any manner; and (iii) notify the sender immediately. In addition, please be aware that any message addressed to our domain is subject to archiving and review by persons other than the intended recipient. Thank you.

FIS Internal Use Only