Hello Joakim,
Thank you very much for the reply and for pointing out the potential problems.
Here are some details: I am unable to upgrade my version of Jetty because I am actually using the latest version of a micro-service framework (
sparkjava.com) that uses Jetty 9.3.6.
I am using a client that comes from the latest version - 2.17.1 - of Apache Camel's AHC (Ning's Async Http Client) because these requests are actually being made through an Apache Camel application that proxies the requests from the users to my web service. Apart from this, it also has a monitoring component which hits the health API using another client.
What's surprising is that both of these clients automatically add the Connection Keep-Alive headers without any intervention from my side. I wonder why they do it.
You are right that web browsers are not the clients that use my web service (apologies for mentioning it as Web Server in my previous mail). There is a proxy that sits in front of my web service which is the client most of the times. This makes me assume that persistent connections won't get used in my scenario. But then when these clients use connection pools and when the connections are returned to the pool and then fetched by the client for another request, wouldn't that be the same connection (and hence a persistent connection?). Or have I got that wrong?
Thanks for the explanation of the stack trace. It helped. Now I can see that there are several places in the log where the connection seems to be closed from the client's side. However all of them seem to be related to the GET /admin/sessionStats call. I have some questions regarding the last part of the log where connections are once again closed, but seem to be due to a different reason. (I have placed the questions/assumptions amidst the logs itself for easier context, prefixed with "======= ").
======= Looks like the DELETE /session/id call begins here:
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.io.ManagedSelector [qtp1809807198-24] Selector loop woken up from select, 1/2 selected
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.io.SelectChannelEndPoint [qtp1809807198-24] onSelected 1->0 r=true w=false for SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,FI,-,1679/3600000,HttpConnection}{io=1/0,kio=1,kro=1}
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.io.SelectChannelEndPoint [qtp1809807198-24] task SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,FI,-,1679/3600000,HttpConnection}{io=1/0,kio=1,kro=1}:runFillable
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-24] EPR Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 produced SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,FI,-,1679/3600000,HttpConnection}{io=1/0,kio=1,kro=1}:runFillable
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-24] EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 dispatch
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.util.thread.QueuedThreadPool [qtp1809807198-24] queue EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-24] EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 run SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,FI,-,1679/3600000,HttpConnection}{io=1/0,kio=1,kro=1}:runFillable
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.io.FillInterest [qtp1809807198-24] FillInterest@125eb2b{true,AC.ReadCB@2e5538d4{HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,FI,-,1679/3600000,HttpConnection}{io=1/0,kio=1,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=5,c=false,a=IDLE,uri=null}]}} fillable AC.ReadCB@2e5538d4{HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,FI,-,1679/3600000,HttpConnection}{io=1/0,kio=1,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=5,c=false,a=IDLE,uri=null}]}
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,1679/3600000,HttpConnection}{io=1/0,kio=1,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=5,c=false,a=IDLE,uri=null}] onFillable enter HttpChannelState@386af3cb{s=IDLE a=null i=true r=!P!U w=false} null
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.io.ChannelEndPoint [qtp1809807198-24] filled 348 SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,1679/3600000,HttpConnection}{io=1/0,kio=1,kro=1}
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,0/3600000,HttpConnection}{io=1/0,kio=1,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=5,c=false,a=IDLE,uri=null}] filled 348 HeapByteBuffer@23328ae9[p=0,l=348,c=8192,r=348]={<<<DELETE /session/2...Accept: */*\r\n\r\n>>>pt: */*\r\n\r\nst: lo...\n1ff6\r\n\xF9\x92\xA9\xB5\x9b"BH}
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,0/3600000,HttpConnection}{io=1/0,kio=1,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=5,c=false,a=IDLE,uri=null}] parse HeapByteBuffer@23328ae9[p=0,l=348,c=8192,r=348]={<<<DELETE /session/2...Accept: */*\r\n\r\n>>>pt: */*\r\n\r\nst: lo...\n1ff6\r\n\xF9\x92\xA9\xB5\x9b"BH} {}
DEBUG 2016-06-23T15:32:31,776 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] parseNext s=START HeapByteBuffer@23328ae9[p=0,l=348,c=8192,r=348]={<<<DELETE /session/2...Accept: */*\r\n\r\n>>>pt: */*\r\n\r\nst: lo...\n1ff6\r\n\xF9\x92\xA9\xB5\x9b"BH}
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] START --> SPACE1
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] SPACE1 --> URI
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] URI --> SPACE2
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] SPACE2 --> REQUEST_VERSION
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] REQUEST_VERSION --> HEADER
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER --> HEADER_IN_VALUE
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER_IN_VALUE --> HEADER
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER --> HEADER_IN_NAME
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER_IN_NAME --> HEADER_VALUE
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER_VALUE --> HEADER_IN_VALUE
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER_IN_VALUE --> HEADER
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER --> HEADER_IN_VALUE
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER_IN_VALUE --> HEADER
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER --> HEADER_IN_VALUE
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER_IN_VALUE --> HEADER
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER --> HEADER_VALUE
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER_VALUE --> HEADER
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER --> HEADER_IN_VALUE
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER_IN_VALUE --> HEADER
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER --> HEADER_IN_VALUE
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER_IN_VALUE --> HEADER
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER --> HEADER_IN_VALUE
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER_IN_VALUE --> HEADER
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER --> HEADER_IN_VALUE
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER_IN_VALUE --> HEADER
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] HEADER --> CHUNKED_CONTENT
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,1/3600000,HttpConnection}{io=1/0,kio=1,kro=1}][p=HttpParser{s=CHUNKED_CONTENT,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=6,c=false,a=IDLE,uri=//localhost:8001/session/221680194155764}] parsed true HttpParser{s=CHUNKED_CONTENT,0 of -1}
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] releaseRequestBuffer HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,1/3600000,HttpConnection}{io=1/0,kio=1,kro=1}][p=HttpParser{s=CHUNKED_CONTENT,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=6,c=false,a=IDLE,uri=//localhost:8001/session/221680194155764}]
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.server.HttpChannel [qtp1809807198-24] HttpChannelOverHttp@1bad154b{r=6,c=false,a=IDLE,uri=//localhost:8001/session/221680194155764} handle //localhost:8001/session/221680194155764
DEBUG 2016-06-23T15:32:31,777 org.eclipse.jetty.server.HttpChannelState [qtp1809807198-24] HttpChannelState@386af3cb{s=IDLE a=null i=true r=!P!U w=false} handling IDLE
DEBUG 2016-06-23T15:32:31,778 org.eclipse.jetty.server.HttpChannel [qtp1809807198-24] HttpChannelOverHttp@1bad154b{r=6,c=false,a=DISPATCHED,uri=//localhost:8001/session/221680194155764} action DISPATCH
DEBUG 2016-06-23T15:32:31,778 org.eclipse.jetty.server.Server [qtp1809807198-24] REQUEST on HttpChannelOverHttp@1bad154b{r=6,c=false,a=DISPATCHED,uri=//localhost:8001/session/221680194155764}
DELETE //localhost:8001/session/221680194155764
Accept-Encoding: gzip,deflate
breadcrumbId: ID-WIN-AJR3DI2M49E-50996-1466695831793-2-18
Cookie: session=221680194155764; session=221680194155764
User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_91)
Content-Type:
Transfer-Encoding: chunked
Connection: keep-alive
Host: localhost:8001
Accept: */*
DEBUG 2016-06-23T15:32:31,778 org.eclipse.jetty.server.session [qtp1809807198-24] sessionManager=org.eclipse.jetty.server.session.HashSessionManager@103a4a2
DEBUG 2016-06-23T15:32:31,778 org.eclipse.jetty.server.session [qtp1809807198-24] session=null
DEBUG 2016-06-23T15:32:31,778 log.requests [qtp1809807198-24] Starting request: DELETE/session/221680194155764
DEBUG 2016-06-23T15:32:31,778 log.requests [qtp1809807198-24] Finished request: DELETE/session/221680194155764
DEBUG 2016-06-23T15:32:31,779 org.eclipse.jetty.util.thread.QueuedThreadPool [qtp1809807198-19] run EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8
DEBUG 2016-06-23T15:32:31,779 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-19] EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 run
DEBUG 2016-06-23T15:32:31,779 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-19] EPR Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 produce enter
DEBUG 2016-06-23T15:32:31,779 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-19] EPR Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 producing
DEBUG 2016-06-23T15:32:31,779 org.eclipse.jetty.io.SelectChannelEndPoint [qtp1809807198-19] Key interests updated 1 -> 0 on SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,3/3600000,HttpConnection}{io=0/0,kio=0,kro=1}
DEBUG 2016-06-23T15:32:31,779 org.eclipse.jetty.io.ManagedSelector [qtp1809807198-19] Selector loop waiting on select
DEBUG 2016-06-23T15:32:31,779 org.eclipse.jetty.server.HttpChannel [qtp1809807198-24] Commit HTTP/1.1{s=200,h=6} to HttpChannelOverHttp@1bad154b{r=6,c=true,a=DISPATCHED,uri=//localhost:8001/session/221680194155764}
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] org.eclipse.jetty.server.HttpConnection$SendCallback@a4b3f2b[PROCESSING][i=HTTP/1.1{s=200,h=6},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@549bd593] generate: NEED_HEADER (null,[p=0,l=0,c=0,r=0],false)@START
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] org.eclipse.jetty.server.HttpConnection$SendCallback@a4b3f2b[PROCESSING][i=HTTP/1.1{s=200,h=6},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@549bd593] generate: FLUSH ([p=0,l=331,c=8192,r=331],[p=0,l=0,c=0,r=0],false)@COMMITTED
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.io.WriteFlusher [qtp1809807198-24] write: WriteFlusher@702da0b3{IDLE} [HeapByteBuffer@649d2c0f[p=0,l=331,c=8192,r=331]={<<<HTTP/1.1 200 OK\r\n....v20151106)\r\n\r\n>>>ng: chunked\r\nConn...742\r\n\xB7\xF4R\t\xF9\xF39o\xF9\xD4}]
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.io.WriteFlusher [qtp1809807198-24] update WriteFlusher@702da0b3{WRITING}:IDLE-->WRITING
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.io.ChannelEndPoint [qtp1809807198-24] flushed 331 SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,W,20/3600000,HttpConnection}{io=0/0,kio=0,kro=1}
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.io.WriteFlusher [qtp1809807198-24] Flushed=true 331/331+0 WriteFlusher@702da0b3{WRITING}
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.io.WriteFlusher [qtp1809807198-24] update WriteFlusher@702da0b3{IDLE}:WRITING-->IDLE
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] org.eclipse.jetty.server.HttpConnection$SendCallback@a4b3f2b[PROCESSING][i=HTTP/1.1{s=200,h=6},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@549bd593] generate: DONE ([p=331,l=331,c=8192,r=0],[p=0,l=0,c=0,r=0],false)@COMMITTED
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] org.eclipse.jetty.server.HttpConnection$SendCallback@a4b3f2b[PROCESSING][i=null,cb=Blocker@2c294b5e{null}] generate: CONTINUE (null,[p=0,l=0,c=0,r=0],true)@COMPLETING
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] org.eclipse.jetty.server.HttpConnection$SendCallback@a4b3f2b[PROCESSING][i=null,cb=Blocker@2c294b5e{null}] generate: NEED_CHUNK (null,[p=0,l=0,c=0,r=0],true)@COMPLETING
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] org.eclipse.jetty.server.HttpConnection$SendCallback@a4b3f2b[PROCESSING][i=null,cb=Blocker@2c294b5e{null}] generate: FLUSH (null,[p=0,l=0,c=0,r=0],true)@COMPLETING
DEBUG 2016-06-23T15:32:31,796 org.eclipse.jetty.io.WriteFlusher [qtp1809807198-24] write: WriteFlusher@702da0b3{IDLE} [HeapByteBuffer@24103a6b[p=0,l=5,c=1024,r=5]={<<<0\r\n\r\n>>>\r\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.io.WriteFlusher [qtp1809807198-24] update WriteFlusher@702da0b3{WRITING}:IDLE-->WRITING
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.io.ChannelEndPoint [qtp1809807198-24] flushed 5 SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,W,1/3600000,HttpConnection}{io=0/0,kio=0,kro=1}
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.io.WriteFlusher [qtp1809807198-24] Flushed=true 5/5+0 WriteFlusher@702da0b3{WRITING}
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.io.WriteFlusher [qtp1809807198-24] update WriteFlusher@702da0b3{IDLE}:WRITING-->IDLE
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] org.eclipse.jetty.server.HttpConnection$SendCallback@a4b3f2b[PROCESSING][i=null,cb=Blocker@2c294b5e{null}] generate: DONE (null,[p=0,l=0,c=0,r=0],true)@END
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.server.Server [qtp1809807198-24] RESPONSE for /session/221680194155764 h=true
200 null
Date: Thu, 23 Jun 2016 15:32:31 GMT
Access-Control-Allow-Origin: *
Set-Cookie: session="";Version=1;Expires=Thu, 01-Jan-1970 00:00:00 GMT;Max-Age=0
Expires: Thu, 01 Jan 1970 00:00:00 GMT
API-Doc-Version: 1.2
Content-Type: text/html;charset=utf-8
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.server.HttpChannelState [qtp1809807198-24] HttpChannelState@386af3cb{s=DISPATCHED a=null i=true r=!P!U w=false} unhandle DISPATCHED
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.server.HttpChannel [qtp1809807198-24] HttpChannelOverHttp@1bad154b{r=6,c=true,a=COMPLETING,uri=//localhost:8001/session/221680194155764} action COMPLETE
======= Question: It seems to me that the DELETE request has been completely handled at this point. I am not able to understand as to why it says "unconsumed input" in the next line. My understanding is that DELETE requests typically don't have any request bodies, so does it mean that in this case the clients are indeed sending some request bodies?
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] unconsumed input HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,0/3600000,HttpConnection}{io=0/0,kio=0,kro=1}][p=HttpParser{s=CHUNKED_CONTENT,0 of -1},g=HttpGenerator@72d1bf77{s=END},c=HttpChannelOverHttp@1bad154b{r=6,c=true,a=COMPLETED,uri=//localhost:8001/session/221680194155764}]
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.io.ChannelEndPoint [qtp1809807198-24] filled 0 SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,0/3600000,HttpConnection}{io=0/0,kio=0,kro=1}
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.io.ChannelEndPoint [qtp1809807198-24] filled 0 SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,0/3600000,HttpConnection}{io=0/0,kio=0,kro=1}
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,0/3600000,HttpConnection}{io=0/0,kio=0,kro=1}][p=HttpParser{s=CHUNKED_CONTENT,0 of -1},g=HttpGenerator@72d1bf77{s=END},c=HttpChannelOverHttp@1bad154b{r=6,c=true,a=COMPLETED,uri=//localhost:8001/session/221680194155764}] filled 0 HeapByteBuffer@23328ae9[p=0,l=0,c=8192,r=0]={<<<>>>DELETE /session/2...\n1ff6\r\n\xF9\x92\xA9\xB5\x9b"BH}
DEBUG 2016-06-23T15:32:31,797 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,0/3600000,HttpConnection}{io=0/0,kio=0,kro=1}][p=HttpParser{s=CHUNKED_CONTENT,0 of -1},g=HttpGenerator@72d1bf77{s=END},c=HttpChannelOverHttp@1bad154b{r=6,c=true,a=COMPLETED,uri=//localhost:8001/session/221680194155764}] parse HeapByteBuffer@23328ae9[p=0,l=0,c=8192,r=0]={<<<>>>DELETE /session/2...\n1ff6\r\n\xF9\x92\xA9\xB5\x9b"BH} {}
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] parseNext s=CHUNKED_CONTENT HeapByteBuffer@23328ae9[p=0,l=0,c=8192,r=0]={<<<>>>DELETE /session/2...\n1ff6\r\n\xF9\x92\xA9\xB5\x9b"BH}
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,1/3600000,HttpConnection}{io=0/0,kio=0,kro=1}][p=HttpParser{s=CHUNKED_CONTENT,0 of -1},g=HttpGenerator@72d1bf77{s=END},c=HttpChannelOverHttp@1bad154b{r=6,c=true,a=COMPLETED,uri=//localhost:8001/session/221680194155764}] parsed false HttpParser{s=CHUNKED_CONTENT,0 of -1}
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] releaseRequestBuffer HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,Open,in,out,-,-,1/3600000,HttpConnection}{io=0/0,kio=0,kro=1}][p=HttpParser{s=CHUNKED_CONTENT,0 of -1},g=HttpGenerator@72d1bf77{s=END},c=HttpChannelOverHttp@1bad154b{r=6,c=true,a=COMPLETED,uri=//localhost:8001/session/221680194155764}]
======= Question: Jetty seems to be closing the connection at this point. Is the unconsumed input the reason for this?
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.io.AbstractEndPoint [qtp1809807198-24] onClose SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,CLOSED,in,out,-,-,1/3600000,HttpConnection}{io=0/0,kio=0,kro=1}
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.io.ChannelEndPoint [qtp1809807198-24] close SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,CLOSED,in,out,-,-,1/3600000,HttpConnection}{io=0/0,kio=0,kro=1}
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.io.ManagedSelector [qtp1809807198-24] Queued change org.eclipse.jetty.io.ManagedSelector$2@6439f7c6 on org.eclipse.jetty.io.ManagedSelector@22edf707 id=0 keys=2 selected=0
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] close HttpParser{s=CHUNKED_CONTENT,0 of -1}
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] CHUNKED_CONTENT --> CLOSE
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.server.HttpChannel [qtp1809807198-24] HttpChannelOverHttp@1bad154b{r=6,c=false,a=IDLE,uri=null} handle exit, result COMPLETE
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] atEOF HttpParser{s=CLOSE,0 of -1}
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,CLOSED,ISHUT,OSHUT,-,-,1/3600000,HttpConnection}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=6,c=false,a=IDLE,uri=null}] filled -1 null
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,CLOSED,ISHUT,OSHUT,-,-,1/3600000,HttpConnection}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=6,c=false,a=IDLE,uri=null}] parse null {}
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] parseNext s=CLOSE HeapByteBuffer@3575e6fc[p=0,l=0,c=0,r=0]={<<<>>>}
DEBUG 2016-06-23T15:32:31,798 org.eclipse.jetty.http.HttpParser [qtp1809807198-24] CLOSE --> CLOSED
======= Assumption: Looks like the connection (client side port: 51177) is closed here by the qtp1809807198-24 thread.
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.io.ManagedSelector [qtp1809807198-19] Selector loop woken up from select, 0/1 selected
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-19] EPR Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 produced org.eclipse.jetty.io.ManagedSelector$2@6439f7c6
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-19] EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 dispatch
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.util.thread.QueuedThreadPool [qtp1809807198-19] queue EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-19] EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 run org.eclipse.jetty.io.ManagedSelector$2@6439f7c6
======= Question: How come another thread (qtp1809807198-19) is now working with the same client side port 51177 when it should have already been closed by another thread qtp1809807198-24? What does "Destroy" actually mean?
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.io.ManagedSelector [qtp1809807198-19] Destroyed SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,CLOSED,ISHUT,OSHUT,-,-,2/3600000,HttpConnection}{io=0/0,kio=-1,kro=-1}
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.io.AbstractConnection [qtp1809807198-19] onClose HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,CLOSED,ISHUT,OSHUT,-,-,2/3600000,HttpConnection}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=6,c=false,a=IDLE,uri=null}]
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.io.AbstractEndPoint [qtp1809807198-19] onClose SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,CLOSED,ISHUT,OSHUT,-,-,2/3600000,HttpConnection}{io=0/0,kio=-1,kro=-1}
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-19] EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 ran org.eclipse.jetty.io.ManagedSelector$2@6439f7c6
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-19] EPR Prod/Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 producing
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.io.ManagedSelector [qtp1809807198-19] Selector loop waiting on select
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.util.thread.QueuedThreadPool [qtp1809807198-18] run EPR Prod/Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-18] EPR Prod/Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 run
DEBUG 2016-06-23T15:32:31,799 org.eclipse.jetty.util.thread.QueuedThreadPool [qtp1809807198-18] ran EPR Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8
DEBUG 2016-06-23T15:32:31,815 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,CLOSED,ISHUT,OSHUT,-,-,1/3600000,HttpConnection}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=6,c=false,a=IDLE,uri=null}] parsed false HttpParser{s=CLOSED,0 of -1}
======= Question: Would it be correct to assume that the client is actually getting the "IOException: Remotely closed" because of the connection getting closed by the server at this point? What is a potential solution for this?
INFO 2016-06-23T15:32:31,815 CONNECTION DEBUG [qtp1809807198-24] Connection closed
java.lang.Throwable
at org.eclipse.jetty.io.AbstractConnection.close(AbstractConnection.java) [jetty-io-9.3.6.v20151106.jar:9.3.6.v20151106]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:235) [jetty-server-9.3.6.v20151106.jar:9.3.6.v20151106]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:261) [jetty-io-9.3.6.v20151106.jar:9.3.6.v20151106]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95) [jetty-io-9.3.6.v20151106.jar:9.3.6.v20151106]
at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:75) [jetty-io-9.3.6.v20151106.jar:9.3.6.v20151106]
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:213) [jetty-util-9.3.6.v20151106.jar:9.3.6.v20151106]
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:147) [jetty-util-9.3.6.v20151106.jar:9.3.6.v20151106]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654) [jetty-util-9.3.6.v20151106.jar:9.3.6.v20151106]
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572) [jetty-util-9.3.6.v20151106.jar:9.3.6.v20151106]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_91]
DEBUG 2016-06-23T15:32:31,815 org.eclipse.jetty.server.HttpConnection [qtp1809807198-24] HttpConnection@2e5538d4[SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,CLOSED,ISHUT,OSHUT,-,-,18/3600000,HttpConnection}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@72d1bf77{s=START},c=HttpChannelOverHttp@1bad154b{r=6,c=false,a=IDLE,uri=null}] onFillable exit HttpChannelState@386af3cb{s=IDLE a=null i=true r=!P!U w=false} null
DEBUG 2016-06-23T15:32:31,815 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-24] EPR Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 ran SelectChannelEndPoint@364d42b3{/
127.0.0.1:51177<->8001,CLOSED,ISHUT,OSHUT,-,-,18/3600000,HttpConnection}{io=0/0,kio=-1,kro=-1}:runFillable
DEBUG 2016-06-23T15:32:31,815 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume [qtp1809807198-24] EPR Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8 produce exit
DEBUG 2016-06-23T15:32:31,815 org.eclipse.jetty.util.thread.QueuedThreadPool [qtp1809807198-24] ran EPR Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@5645d0c8
-- end of logs --
Thank you very much for your help. I really appreciate it.