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}_______________________________________________
jetty-users mailing list
jetty-users@eclipse.org
To unsubscribe from this list, visit
https://www.eclipse.org/mailman/listinfo/jetty-users
