Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
[jetty-users] incorrect http 200 response while shutting down jetty
  • From: "Robben, Bert" <Bert.Robben@xxxxxxxxxxxxx>
  • Date: Thu, 7 Jul 2022 13:46:35 +0000
  • Accept-language: en-US
  • Arc-authentication-results: i=1; mx.microsoft.com 1; spf=pass smtp.mailfrom=fisglobal.com; dmarc=pass action=none header.from=fisglobal.com; dkim=pass header.d=fisglobal.com; arc=none
  • Arc-message-signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=microsoft.com; s=arcselector9901; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-AntiSpam-MessageData-ChunkCount:X-MS-Exchange-AntiSpam-MessageData-0:X-MS-Exchange-AntiSpam-MessageData-1; bh=elKUevpjp68HNCR7WoAfHnsnd3Mf6fi7nMNagh0GpR8=; b=dvsLp5YMr2QrFVeIo+CPnMNYLn9zV3W+WD40RkyyFC+5qSdCQmeSiKtUPdS1yW1lHyoTPH2vHq8hGUM6ljN1O40BizkiwyrlIJQo1xs5d5NAmv185DGTRrJhYAAypQmzbSBlcKjmUmRgdr3rmf4kKeE4RqvBtJnmUbsQ4YcPO21JqQM9qOylY9lssQq9CigSxxcG9Dkg3s7fR2DI7xWPoZVzTES+Am5H6UBDAg7UoGyQM2YDznO6izIhhUrtsYGSxTxtBCEWX/iz04uRMMl0dB4vRFiBN0bjG8dtP85xe/3SLmYLZZWp2XU2O8jtPh+D7mLCzqrj8htkOYCQ4dLKvA==
  • Arc-seal: i=1; a=rsa-sha256; s=arcselector9901; d=microsoft.com; cv=none; b=n2Qy0F0tWG/XWmWbwVu1wIQM687FmM20gHvxIWwReaZWwGrHX/jtpzgYils1Zr1e/LH7OzONdzauS2V1SJWliISsxHEIA5d9762Q8NO1gyAOPjFX9ZZyu7QjLYQdoIbppdrzln9otsQHpDirXjNDJLd7sBtzjXBNKPlQGRhCk64lDVu4/ypfdQyaQ/oqK7IMjxXLrKdinBaDrGYPhM5Zli5spyTN3MVMrp9RR1AWnEr5Kew1Vdcwya+oRSXjKBetSoS9djDBUOcXKt7UtJvnglzqaRJpWbe4eRi/Earkv9ojlZvGqx9DlLkdbdga2udd2He9uXUJu+0URkXwlkr15A==
  • Delivered-to: jetty-users@xxxxxxxxxxx
  • Disclaimersource: eop
  • List-archive: <https://www.eclipse.org/mailman/private/jetty-users/>
  • List-help: <mailto:jetty-users-request@eclipse.org?subject=help>
  • List-subscribe: <https://www.eclipse.org/mailman/listinfo/jetty-users>, <mailto:jetty-users-request@eclipse.org?subject=subscribe>
  • List-unsubscribe: <https://www.eclipse.org/mailman/options/jetty-users>, <mailto:jetty-users-request@eclipse.org?subject=unsubscribe>
  • Msip_labels: MSIP_Label_9e1e58c1-766d-4ff4-9619-b604fc37898b_ActionId=35542c21-19c1-4507-93e1-c45361f5a4dc; MSIP_Label_9e1e58c1-766d-4ff4-9619-b604fc37898b_ContentBits=0; MSIP_Label_9e1e58c1-766d-4ff4-9619-b604fc37898b_Enabled=true; MSIP_Label_9e1e58c1-766d-4ff4-9619-b604fc37898b_Method=Standard; MSIP_Label_9e1e58c1-766d-4ff4-9619-b604fc37898b_Name=Internal Use; MSIP_Label_9e1e58c1-766d-4ff4-9619-b604fc37898b_SetDate=2022-07-07T13:07:51Z; MSIP_Label_9e1e58c1-766d-4ff4-9619-b604fc37898b_SiteId=e3ff91d8-34c8-4b15-a0b4-18910a6ac575;
  • Thread-index: AdiSApzTV2tsliQaQQaZkBZSookX+w==
  • Thread-topic: incorrect http 200 response while shutting down jetty

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

Jul 7, 2022 @ 14:48:02.005	c.c.n.a.r.api.internal.AkkaWebServer	Gracefully stopping Jetty server	251,964,943
Jul 7, 2022 @ 14:48:02.007	o.e.jetty.server.HttpConnection	@25dc7725::SocketChannelEndPoint@25d44276{l=/10.129.10.66:8080,r=/10.129.8.1:34180,OPEN,fill=-,flush=-,to=611/34321}{io=1/0,kio=1,kro=1}->@25dc7725[p=HttpParser{s=START,0 of -1},g=HttpGenerator@5642ad08{s=START}]=>@2e619a54{s=HttpChannelState@704fbb75{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=132,c=false/false,a=IDLE,uri=null,age=0} onFillable enter HttpChannelState@704fbb75{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0} null	251,966,021
Jul 7, 2022 @ 14:48:02.008	o.e.jetty.server.HttpConnection	@25dc7725::SocketChannelEndPoint@25d44276{l=/10.129.10.66:8080,r=/10.129.8.1:34180,OPEN,fill=-,flush=-,to=0/34321}{io=1/0,kio=1,kro=1}->@25dc7725[p=HttpParser{s=START,0 of -1},g=HttpGenerator@5642ad08{s=START}]=>@2e619a54{s=HttpChannelState@704fbb75{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=132,c=false/false,a=IDLE,uri=null,age=0} filled 463 HeapByteBuffer@366c9f06[p=0,l=463,c=8192,r=463]={<<<POST /test-product/v1/saf...2-07-07T12:48:01.966Z"}>>>pmieuclyg...\x00\x00\x00\x00\x00\x00\x00}	251,966,675
Jul 7, 2022 @ 14:48:02.008	o.e.jetty.server.HttpConnection	@25dc7725::SocketChannelEndPoint@25d44276{l=/10.129.10.66:8080,r=/10.129.8.1:34180,OPEN,fill=-,flush=-,to=0/34321}{io=1/0,kio=1,kro=1}->@25dc7725[p=HttpParser{s=START,0 of -1},g=HttpGenerator@5642ad08{s=START}]=>@2e619a54{s=HttpChannelState@704fbb75{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=132,c=false/false,a=IDLE,uri=null,age=0} parse HeapByteBuffer@366c9f06[p=0,l=463,c=8192,r=463]={<<<POST /test-product/v1/saf...2-07-07T12:48:01.966Z"}>>>pmieuclyg...\x00\x00\x00\x00\x00\x00\x00} {}	251,967,409
Jul 7, 2022 @ 14:48:02.008	org.eclipse.jetty.server.HttpChannel	REQUEST for //test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish on @2e619a54{s=HttpChannelState@704fbb75{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=133,c=false/false,a=IDLE,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=0}	251,968,141
Jul 7, 2022 @ 14:48:02.009	o.e.jetty.server.HttpConnection	@25dc7725::SocketChannelEndPoint@25d44276{l=/10.129.10.66:8080,r=/10.129.8.1:34180,OPEN,fill=-,flush=-,to=1/34321}{io=1/0,kio=1,kro=1}->@25dc7725[p=HttpParser{s=CONTENT,0 of 131},g=HttpGenerator@5642ad08{s=START}]=>@2e619a54{s=HttpChannelState@704fbb75{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=133,c=false/false,a=IDLE,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=1} parsed true HttpParser{s=CONTENT,0 of 131}	251,969,764
Jul 7, 2022 @ 14:48:02.009	org.eclipse.jetty.server.HttpChannel	handle //test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish @2e619a54{s=HttpChannelState@704fbb75{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=133,c=false/false,a=IDLE,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=1} 	251,970,413
Jul 7, 2022 @ 14:48:02.009	o.e.jetty.server.HttpChannelState	handling HttpChannelState@704fbb75{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0}	251,970,879
Jul 7, 2022 @ 14:48:02.009	org.eclipse.jetty.server.HttpChannel	action DISPATCH @2e619a54{s=HttpChannelState@704fbb75{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=133,c=false/false,a=HANDLING,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=1}	251,971,150
Jul 7, 2022 @ 14:48:02.009	org.eclipse.jetty.server.Server	REQUEST POST /test-product/v1/saf/jms/publish on @2e619a54{s=HttpChannelState@704fbb75{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=133,c=false/false,a=HANDLING,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=1}	251,971,561
Jul 7, 2022 @ 14:48:02.009	o.e.j.server.handler.ContextHandler	scope null||/test-product/v1/saf/jms/publish @ o.e.j.s.ServletContextHandler@79009bde{/,null,AVAILABLE,@ClusterMigrationServerConnector}	251,972,000
Jul 7, 2022 @ 14:48:02.009	o.e.j.server.handler.ContextHandler	scope null||/test-product/v1/saf/jms/publish @ o.e.j.s.ServletContextHandler@1e680c92{/,null,AVAILABLE}	251,972,308
Jul 7, 2022 @ 14:48:02.010	o.e.j.server.handler.ContextHandler	=[qtp2119123648-499#null@6b44d11a]=context=||/test-product/v1/saf/jms/publish @ o.e.j.s.ServletContextHandler@1e680c92{/,null,AVAILABLE}	251,972,583
Jul 7, 2022 @ 14:48:02.010	o.e.j.s.h.AbstractHandlerContainer	=[test-product-akka.actor.internal-dispatcher-21]=Graceful shutdown Server@46753be0{STOPPING}[9.4.46.v20220331] by 	251,972,870
Jul 7, 2022 @ 14:48:02.015	o.e.jetty.server.HttpConnection	=[qtp2119123648-499#null@6b44d11a]=@25dc7725::SocketChannelEndPoint@25d44276{l=/10.129.10.66:8080,r=/10.129.8.1:34180,OPEN,fill=-,flush=-,to=7/34321}{io=0/0,kio=0,kro=1}->@25dc7725[p=HttpParser{s=CONTENT,0 of 131},g=HttpGenerator@5642ad08{s=START}]=>@2e619a54{s=HttpChannelState@704fbb75{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=133,c=false/false,a=HANDLING,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=7} parse HeapByteBuffer@366c9f06[p=332,l=463,c=8192,r=131]={POST /tes...131\r\n\r\n<<<{"id":"b5fa8319-2261-4eb6...2-07-07T12:48:01.966Z"}>>>pmieuclyg...\x00\x00\x00\x00\x00\x00\x00} {}	251,976,601
Jul 7, 2022 @ 14:48:02.015	org.eclipse.jetty.server.HttpChannel	=[qtp2119123648-499#null@6b44d11a]=onContent @2e619a54{s=HttpChannelState@704fbb75{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=133,c=false/false,a=HANDLING,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=7} Content@75054e2e{HeapByteBufferR@5794d9e0[p=332,l=463,c=8192,r=131]={POST /tes...131\r\n\r\n<<<{"id":"b5fa8319-2261-4eb6...2-07-07T12:48:01.966Z"}>>>pmieuclyg...\x00\x00\x00\x00\x00\x00\x00}}	251,978,225
Jul 7, 2022 @ 14:48:02.015	org.eclipse.jetty.server.HttpInput	=[qtp2119123648-499#null@6b44d11a]=HttpInputOverHTTP@5a8d4474[c=0,q=0,[0]=null,s=STREAM] addContent Content@75054e2e{HeapByteBufferR@5794d9e0[p=332,l=463,c=8192,r=131]={POST /tes...131\r\n\r\n<<<{"id":"b5fa8319-2261-4eb6...2-07-07T12:48:01.966Z"}>>>pmieuclyg...\x00\x00\x00\x00\x00\x00\x00}}	251,980,525
Jul 7, 2022 @ 14:48:02.016	org.eclipse.jetty.server.HttpChannel	=[qtp2119123648-499#null@6b44d11a]=onContentComplete @2e619a54{s=HttpChannelState@704fbb75{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=133,c=false/false,a=HANDLING,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=8}	251,981,668
Jul 7, 2022 @ 14:48:02.016	org.eclipse.jetty.server.HttpChannel	=[qtp2119123648-499#null@6b44d11a]=onRequestComplete @2e619a54{s=HttpChannelState@704fbb75{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=133,c=false/false,a=HANDLING,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=8}	251,992,563
Jul 7, 2022 @ 14:48:02.019	org.eclipse.jetty.server.HttpInput	=[qtp2119123648-499#null@6b44d11a]=HttpInputOverHTTP@5a8d4474[c=0,q=1,[0]=EOF,s=STREAM] addContent EOF	251,994,140
Jul 7, 2022 @ 14:48:02.019	o.e.jetty.server.HttpConnection	=[qtp2119123648-499#null@6b44d11a]=@25dc7725::SocketChannelEndPoint@25d44276{l=/10.129.10.66:8080,r=/10.129.8.1:34180,OPEN,fill=-,flush=-,to=11/34321}{io=0/0,kio=0,kro=1}->@25dc7725[p=HttpParser{s=END,131 of 131},g=HttpGenerator@5642ad08{s=START}]=>@2e619a54{s=HttpChannelState@704fbb75{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=133,c=false/false,a=HANDLING,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=11} parsed false HttpParser{s=END,131 of 131}	251,996,468
Jul 7, 2022 @ 14:48:02.019	o.e.jetty.server.HttpChannelState	=[qtp2119123648-499#null@6b44d11a]=startAsync HttpChannelState@704fbb75{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0}	252,012,580
Jul 7, 2022 @ 14:48:02.021	org.eclipse.jetty.server.HttpInput	=[qtp2119123648-499#null@6b44d11a]=HttpInputOverHTTP@5a8d4474[c=131,q=1,[0]=EOF,s=STREAM] read 131 from Content@75054e2e{HeapByteBufferR@5794d9e0[p=463,l=463,c=8192,r=0]={POST /tes....966Z"}<<<>>>pmieuclyg...\x00\x00\x00\x00\x00\x00\x00}}	252,013,109
Jul 7, 2022 @ 14:48:02.022	o.e.jetty.server.HttpConnection	=[qtp2119123648-499#null@6b44d11a]=releaseRequestBuffer @25dc7725::SocketChannelEndPoint@25d44276{l=/10.129.10.66:8080,r=/10.129.8.1:34180,OPEN,fill=-,flush=-,to=14/34321}{io=0/0,kio=0,kro=1}->@25dc7725[p=HttpParser{s=END,131 of 131},g=HttpGenerator@5642ad08{s=START}]=>@2e619a54{s=HttpChannelState@704fbb75{s=HANDLING rs=ASYNC os=OPEN is=IDLE awp=false se=false i=true al=0},r=133,c=false/false,a=HANDLING,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=14}	252,014,841
Jul 7, 2022 @ 14:48:02.026	org.eclipse.jetty.server.HttpChannel	sendResponse info=null content=HeapByteBuffer@2d3def8b[p=0,l=0,c=0,r=0]={<<<>>>} complete=false committing=true callback=Blocker@8cb748c{null}	252,022,375
Jul 7, 2022 @ 14:48:02.027	o.e.jetty.server.HttpChannelOverHttp	Committing HTTP/1.1{s=200,h=1,cl=-1} @2e619a54{s=HttpChannelState@704fbb75{s=HANDLING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=true al=2},r=133,c=false/false,a=HANDLING,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=19}	252,022,720
Jul 7, 2022 @ 14:48:02.027	org.eclipse.jetty.server.HttpChannel	COMMIT for /test-product/v1/saf/jms/publish on @2e619a54{s=HttpChannelState@704fbb75{s=HANDLING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=true al=2},r=133,c=false/false,a=HANDLING,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=19}	252,027,301
Jul 7, 2022 @ 14:48:02.027	o.e.jetty.server.HttpConnection	generate: NEED_HEADER for SendCallback@57602f85[PROCESSING][i=HTTP/1.1{s=200,h=1,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@264aa750] (null,[p=0,l=0,c=0,r=0],false)@START	252,028,152
Jul 7, 2022 @ 14:48:02.027	o.e.jetty.server.HttpConnection	generate: FLUSH for SendCallback@57602f85[PROCESSING][i=HTTP/1.1{s=200,h=1,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@264aa750] ([p=0,l=143,c=8192,r=143],[p=0,l=0,c=0,r=0],false)@COMMITTED	252,028,507
Jul 7, 2022 @ 14:48:02.027	o.e.jetty.server.HttpConnection	generate: DONE for SendCallback@57602f85[PROCESSING][i=HTTP/1.1{s=200,h=1,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@264aa750] ([p=143,l=143,c=8192,r=0],[p=0,l=0,c=0,r=0],false)@COMMITTED	252,028,880
Jul 7, 2022 @ 14:48:02.028	org.eclipse.jetty.server.HttpOutput	onWriteComplete(false,null) s=OPEN,api=BLOCKED,sc=false,e=null->s=OPEN,api=BLOCKING,sc=false,e=null c=null cb=null w=false	252,029,252
Jul 7, 2022 @ 14:48:02.028	org.eclipse.jetty.server.Server	handled=true async=true committed=true on @2e619a54{s=HttpChannelState@704fbb75{s=HANDLING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=true al=2},r=133,c=false/false,a=HANDLING,uri=//test-product.na-test-product.svc:8080/test-product/v1/saf/jms/publish,age=20}

Back to the top