search

jetty / jetty.project

Eclipse Jetty® - Web Container & Clients - supports HTTP/2, HTTP/1.1, HTTP/1.0, websocket, servlets, and more
https://eclipse.dev/jetty
Other
3.85k stars 1.91k forks source link

Connection paused for a long time in DuplexConnectionPool after created #4728

Closed zhaowenxishi closed 3 years ago

zhaowenxishi commented 4 years ago

Jetty version 9.4.19.v20190610

Java version

OS type/version

Description We use jetty client api to send request, connection created quickly(in TCP level) and then paused for a long time in DuplexConnectionPool after created. The quest is send to nginx(revers proxy). Nginx has a limit "client_header_timeout"(for example 90s). Jetty-client and nginx got handshake in TCP level quickly , but jetty-client say "client hello" in 90s after TCP handshake, so nginx give up the connection.Finally, jetty-client result in a "EOF”. Here are the debug logs below:

Line 53609: 2020-03-24 18:24:48,962 DEBUG [qtp1544790089-51][ROOT][org.eclipse.jetty.io.ManagedSelector  223] Connected true java.nio.channels.SocketChannel[connected local=/111.222.33.44:66666 remote=/111.222.33.44:77777]
Line 53618: 2020-03-24 18:24:48,963 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.util.thread.QueuedThreadPool$Runner  916] run CreateEndPoint@4d46c52f{Connect@2987af3b{java.nio.channels.SocketChannel[connected local=/111.222.33.44:66666 remote=/111.222.33.44:77777],{ssl.peer.port=77777, ssl.peer.host=111.222.33.44, http.destination=HttpDestination[https://111.222.33.44:77777]@c7ad54,queue=0,pool=DuplexConnectionPool@38224df7[c=45/50,a=28,i=12], http.connection.promise=org.eclipse.jetty.client.HttpClient$1$1@3ced5443, client.connector=HttpClient@795e3224{STARTED}}},sun.nio.ch.SelectionKeyImpl@70b564a7} in QueuedThreadPool[qtp1544790089]@5c13a049{STARTED,8<=46<=200,i=12,r=8,q=1}[ReservedThreadExecutor@847dcec{s=3/8,p=0}]
Line 53619: 2020-03-24 18:24:48,963 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.IdleTimeout  161] SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}-><null> idle timeout check, elapsed: 0 ms, remaining: 300000 ms
Line 53624: 2020-03-24 18:24:48,963 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.client.http.HttpClientTransportOverHTTP  62] Created HttpConnectionOverHTTP@77e2aed9::DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}
Line 53628: 2020-03-24 18:24:48,963 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.AbstractEndPoint  344] onOpen SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=IDLE,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53628: 2020-03-24 18:24:48,963 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.AbstractEndPoint  344] onOpen SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=IDLE,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53628: 2020-03-24 18:24:48,963 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.AbstractEndPoint  344] onOpen SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=IDLE,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53632: 2020-03-24 18:24:48,963 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.AbstractConnection  199] onOpen SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=IDLE,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53632: 2020-03-24 18:24:48,963 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.AbstractConnection  199] onOpen SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=IDLE,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53632: 2020-03-24 18:24:48,963 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.AbstractConnection  199] onOpen SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=IDLE,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53633: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.AbstractConnection  199] onOpen HttpConnectionOverHTTP@77e2aed9::DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}
Line 53636: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.AbstractConnection  133] fillInterested HttpConnectionOverHTTP@77e2aed9::DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}
Line 53638: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.FillInterest  79] interested FillInterest@67c6d96c{AC.ReadCB@77e2aed9{HttpConnectionOverHTTP@77e2aed9::DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}}}
Line 53639: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint  699] >needFillInterest uf=false SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=IDLE,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53639: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint  699] >needFillInterest uf=false SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=IDLE,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53639: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint  699] >needFillInterest uf=false SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=IDLE,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53645: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint  1149] ensureFillInterested SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=1/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53645: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint  1149] ensureFillInterested SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=1/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53645: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint  1149] ensureFillInterested SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=-,flush=-,to=1/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53647: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.FillInterest  79] interested FillInterest@4fcfc8e5{SSLC.NBReadCB@6942bb2d{SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]}}
Line 53647: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.FillInterest  79] interested FillInterest@4fcfc8e5{SSLC.NBReadCB@6942bb2d{SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]}}
Line 53647: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.FillInterest  79] interested FillInterest@4fcfc8e5{SSLC.NBReadCB@6942bb2d{SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}{io=0/0,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]}}
Line 53650: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ChannelEndPoint  418] changeInterests p=false 0->1 for SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}{io=0/1,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53650: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ChannelEndPoint  418] changeInterests p=false 0->1 for SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}{io=0/1,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53650: 2020-03-24 18:24:48,964 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ChannelEndPoint  418] changeInterests p=false 0->1 for SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}{io=0/1,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53654: 2020-03-24 18:24:48,965 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.client.AbstractConnectionPool$1  128] Connection 45/50 creation succeeded HttpConnectionOverHTTP@77e2aed9::DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}
Line 53656: 2020-03-24 18:24:48,965 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.client.AbstractConnectionPool  181] Connection idle HttpConnectionOverHTTP@77e2aed9::DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}
Line 53659: 2020-03-24 18:24:48,965 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ManagedSelector  270] Created SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}{io=0/1,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=1/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53659: 2020-03-24 18:24:48,965 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ManagedSelector  270] Created SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}{io=0/1,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=1/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53659: 2020-03-24 18:24:48,965 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.io.ManagedSelector  270] Created SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=0/300000}{io=0/1,kio=0,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=1/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53662: 2020-03-24 18:24:48,965 DEBUG [qtp1544790089-175][ROOT][org.eclipse.jetty.util.thread.QueuedThreadPool$Runner  919] ran CreateEndPoint@4d46c52f{Connect@2987af3b{java.nio.channels.SocketChannel[connected local=/111.222.33.44:66666 remote=/111.222.33.44:77777],{ssl.peer.port=77777, ssl.engine=7bcc4cdd[SSLEngine[hostname=111.222.33.44 port=77777] SSL_NULL_WITH_NULL_NULL], ssl.peer.host=111.222.33.44, http.destination=HttpDestination[https://111.222.33.44:77777]@c7ad54,queue=0,pool=DuplexConnectionPool@38224df7[c=45/50,a=28,i=13], http.connection.promise=org.eclipse.jetty.client.HttpClient$1$1@3ced5443, client.connector=HttpClient@795e3224{STARTED}}},sun.nio.ch.SelectionKeyImpl@70b564a7} in QueuedThreadPool[qtp1544790089]@5c13a049{STARTED,8<=46<=200,i=12,r=8,q=1}[ReservedThreadExecutor@847dcec{s=3/8,p=0}]
Line 53665: 2020-03-24 18:24:48,963 DEBUG [qtp1544790089-51][ROOT][org.eclipse.jetty.util.thread.QueuedThreadPool  520] queue CreateEndPoint@4d46c52f{Connect@2987af3b{java.nio.channels.SocketChannel[connected local=/111.222.33.44:66666 remote=/111.222.33.44:77777],{ssl.peer.port=77777, ssl.peer.host=111.222.33.44, http.destination=HttpDestination[https://111.222.33.44:77777]@c7ad54,queue=0,pool=DuplexConnectionPool@38224df7[c=45/50,a=28,i=12], http.connection.promise=org.eclipse.jetty.client.HttpClient$1$1@3ced5443, client.connector=HttpClient@795e3224{STARTED}}},sun.nio.ch.SelectionKeyImpl@70b564a7} startThread=false
Line 56010: 2020-03-24 18:24:49,127 DEBUG [qtp1544790089-38][ROOT][org.eclipse.jetty.io.ChannelEndPoint  384] Key interests updated 0 -> 1 on SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=163/300000}{io=1/1,kio=1,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=163/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 56010: 2020-03-24 18:24:49,127 DEBUG [qtp1544790089-38][ROOT][org.eclipse.jetty.io.ChannelEndPoint  384] Key interests updated 0 -> 1 on SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=163/300000}{io=1/1,kio=1,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=163/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 56010: 2020-03-24 18:24:49,127 DEBUG [qtp1544790089-38][ROOT][org.eclipse.jetty.io.ChannelEndPoint  384] Key interests updated 0 -> 1 on SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=163/300000}{io=1/1,kio=1,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=163/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 56021: 2020-03-24 18:24:49,128 DEBUG [qtp1544790089-38][ROOT][org.eclipse.jetty.io.ChannelEndPoint  384] Key interests updated 1 -> 1 on SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=163/300000}{io=1/1,kio=1,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=164/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 56021: 2020-03-24 18:24:49,128 DEBUG [qtp1544790089-38][ROOT][org.eclipse.jetty.io.ChannelEndPoint  384] Key interests updated 1 -> 1 on SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=163/300000}{io=1/1,kio=1,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=164/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 56021: 2020-03-24 18:24:49,128 DEBUG [qtp1544790089-38][ROOT][org.eclipse.jetty.io.ChannelEndPoint  384] Key interests updated 1 -> 1 on SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=163/300000}{io=1/1,kio=1,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=164/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=null)[send=HttpSenderOverHTTP@128744dd(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@66eef42a{s=START}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]

--------------????paused such a long time????-------------------------------------------

Line 53495: 2020-03-24 18:26:18,746 DEBUG [http-nio-auto-1-exec-83][ROOT][org.eclipse.jetty.client.AbstractConnectionPool  161] Connection active HttpConnectionOverHTTP@77e2aed9::DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89782/300000}
Line 53496: 2020-03-24 18:26:18,746 DEBUG [http-nio-auto-1-exec-83][ROOT][org.eclipse.jetty.client.HttpDestination  315] Processing exchange HttpExchange@37623efe req=PENDING/null@null res=PENDING/null@null on HttpConnectionOverHTTP@77e2aed9::DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89782/300000} of HttpDestination[https://111.222.33.44:77777]@c7ad54,queue=0,pool=DuplexConnectionPool@38224df7[c=14/50,a=10,i=4]
Line 53537: 2020-03-24 18:26:18,748 DEBUG [http-nio-auto-1-exec-83][ROOT][org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint  832] >flush SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89784/300000}{io=1/1,kio=1,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=W,to=89784/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=HttpExchange@37623efe req=PENDING/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@128744dd(req=HEADERS,snd=SENDING,failure=null)[HttpGenerator@66eef42a{s=COMPLETING}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53537: 2020-03-24 18:26:18,748 DEBUG [http-nio-auto-1-exec-83][ROOT][org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint  832] >flush SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89784/300000}{io=1/1,kio=1,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=W,to=89784/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=HttpExchange@37623efe req=PENDING/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@128744dd(req=HEADERS,snd=SENDING,failure=null)[HttpGenerator@66eef42a{s=COMPLETING}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53537: 2020-03-24 18:26:18,748 DEBUG [http-nio-auto-1-exec-83][ROOT][org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint  832] >flush SslConnection@6942bb2d::SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89784/300000}{io=1/1,kio=1,kro=8}->SslConnection@6942bb2d{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=W,to=89784/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=HttpExchange@37623efe req=PENDING/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@128744dd(req=HEADERS,snd=SENDING,failure=null)[HttpGenerator@66eef42a{s=COMPLETING}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53599: 2020-03-24 18:26:18,757 DEBUG [qtp1544790089-43][ROOT][org.eclipse.jetty.io.ManagedSelector$SelectorProducer  519] selected 1 sun.nio.ch.SelectionKeyImpl@70b564a7 SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89792/300000}{io=1/1,kio=1,kro=1}->SslConnection@6942bb2d{NEED_UNWRAP,eio=-1/0,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=W,to=89793/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=HttpExchange@37623efe req=PENDING/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@128744dd(req=HEADERS,snd=SENDING,failure=null)[HttpGenerator@66eef42a{s=COMPLETING}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]] 
Line 53599: 2020-03-24 18:26:18,757 DEBUG [qtp1544790089-43][ROOT][org.eclipse.jetty.io.ManagedSelector$SelectorProducer  519] selected 1 sun.nio.ch.SelectionKeyImpl@70b564a7 SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89792/300000}{io=1/1,kio=1,kro=1}->SslConnection@6942bb2d{NEED_UNWRAP,eio=-1/0,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=W,to=89793/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=HttpExchange@37623efe req=PENDING/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@128744dd(req=HEADERS,snd=SENDING,failure=null)[HttpGenerator@66eef42a{s=COMPLETING}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]] 
Line 53599: 2020-03-24 18:26:18,757 DEBUG [qtp1544790089-43][ROOT][org.eclipse.jetty.io.ManagedSelector$SelectorProducer  519] selected 1 sun.nio.ch.SelectionKeyImpl@70b564a7 SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89792/300000}{io=1/1,kio=1,kro=1}->SslConnection@6942bb2d{NEED_UNWRAP,eio=-1/0,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=W,to=89793/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=HttpExchange@37623efe req=PENDING/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@128744dd(req=HEADERS,snd=SENDING,failure=null)[HttpGenerator@66eef42a{s=COMPLETING}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]] 
Line 53602: 2020-03-24 18:26:18,757 DEBUG [qtp1544790089-43][ROOT][org.eclipse.jetty.io.ChannelEndPoint  344] onSelected 1->0 r=true w=false for SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89793/300000}{io=1/0,kio=1,kro=1}->SslConnection@6942bb2d{NEED_UNWRAP,eio=-1/0,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=W,to=89793/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=HttpExchange@37623efe req=PENDING/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@128744dd(req=HEADERS,snd=SENDING,failure=null)[HttpGenerator@66eef42a{s=COMPLETING}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53602: 2020-03-24 18:26:18,757 DEBUG [qtp1544790089-43][ROOT][org.eclipse.jetty.io.ChannelEndPoint  344] onSelected 1->0 r=true w=false for SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89793/300000}{io=1/0,kio=1,kro=1}->SslConnection@6942bb2d{NEED_UNWRAP,eio=-1/0,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=W,to=89793/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=HttpExchange@37623efe req=PENDING/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@128744dd(req=HEADERS,snd=SENDING,failure=null)[HttpGenerator@66eef42a{s=COMPLETING}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53602: 2020-03-24 18:26:18,757 DEBUG [qtp1544790089-43][ROOT][org.eclipse.jetty.io.ChannelEndPoint  344] onSelected 1->0 r=true w=false for SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89793/300000}{io=1/0,kio=1,kro=1}->SslConnection@6942bb2d{NEED_UNWRAP,eio=-1/0,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=W,to=89793/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=HttpExchange@37623efe req=PENDING/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@128744dd(req=HEADERS,snd=SENDING,failure=null)[HttpGenerator@66eef42a{s=COMPLETING}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
Line 53736: 2020-03-24 18:26:18,757 DEBUG [qtp1544790089-43][ROOT][org.eclipse.jetty.io.ChannelEndPoint  356] task CEP:SocketChannelEndPoint@11207233{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=-,to=89793/300000}{io=1/0,kio=1,kro=1}->SslConnection@6942bb2d{NEED_UNWRAP,eio=-1/0,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@7b61ff98{/111.222.33.44:77777<->/111.222.33.44:66666,OPEN,fill=FI,flush=W,to=89793/300000}=>HttpConnectionOverHTTP@77e2aed9(l:/111.222.33.44:66666 <-> r:/111.222.33.44:77777,closed=false)=>HttpChannelOverHTTP@70f1b87c(exchange=HttpExchange@37623efe req=PENDING/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@128744dd(req=HEADERS,snd=SENDING,failure=null)[HttpGenerator@66eef42a{s=COMPLETING}],recv=HttpReceiverOverHTTP@1a09b009(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]:runFillable:BLOCKING
sbordet commented 4 years ago

This is normal behavior.

The client may need to create a new connection in response to a new request being sent, typically during a load spike. However, it may happen that by the time the connection is created, a previous connection frees up and the request is sent in the freed up connection rather than in the newly created one.

So the newly created connection goes back into the pool to possibly serve other requests. In your case the newly created connection remains idle in the pool.

Your client configuration has an idle timeout of 300000 ms i.e. 5 minutes. If the server (nginx) has an idle timeout of 90 seconds, then you risk that the client picks up a connection that is about to be closed by the server. This is also a very common case, and it's enough to configure the client with an idle timeout that is smaller than the server.

Configure your client with a 75 seconds idle timeout if your server has 90 seconds, and all will be good (and don't worry about these spurious connections that are being created during load spikes).

Let know if the configuration changes resolved your issue.

zhaowenxishi commented 4 years ago

Thanks a lot , I will try it later. By the way, I also want to ask a question about the "timeout". I use FutureResponseListener to handle a "so called Synchronous request", we need to set a "timeout" which counts the waiting time for response after request. In a addition, jetty also has a "idletimeout" which indicates the time period that nothing transport on the channel. For your suggestions, I can set ildetimeout to 75 seconds(need smaller than server-nginx 90s). But what if I do need a timeout=90s or larger beacuse the Server-end has plenty of tasks to handle. In this situation, i have to set "timeout"(FutureResponseListener)=90s. Then "timeout" is smaller than "idletimeout". I've tested the situation(timeout<idletimeout) before. Finally the "idletimeout" will work beacuse it's smaller, and I got a TimeoutExceptoin(75s). The two TIMEOUT seem to not independent and it's hard to have a balance.

sbordet commented 4 years ago

FutureResponseListener has the semantic of a total timeout and it is equivalent to Request.timeout(...). Both account for the total time request + response take to complete.

But what if I do need a timeout=90s or larger beacuse the Server-end has plenty of tasks to handle.

Then your Nginx configuration is too small. And if it takes more than 90s for a request to complete, you have other problems than the idle timeout :smiley:

You can use Request.idleTimeout(...) but you will be at the mercy of the Nginx idle timeout.

Total timeout and idle timeout serve different purposes and are orthogonal (and therefore independent).

The "balance" you are looking for is entirely dependent on your application. Jetty can only give you configuration parameters, the rest is up to you as Jetty cannot know what your application does.

zhaowenxishi commented 4 years ago

Thanks a lot. But I may still don't understand clearly.

I think there is a gap between jetty-client and nginx about the definitions of some TIMEOUT. My situation is like this.

JETTY(client)<----------->NGINX(reverse proxy)<---------->TOMCAT(server)

JETTY: (1)totalTimeout (2)idletimeout NGINX: (1)proxy_read_timeout:Defines a timeout for reading a response from the proxied server. As client-end developer, I set jetty-totalTimeout at the merce of this. (2)keepalive_timeout:during which a keep-alive client connection will stay open on the server side. As client-end developer, I set jetty-totalTimeout at the merce of this. I don't know the details of designing before,but we finally set proxy_read_timeout=500s, keepalive_timeout=90s maybe based on overall efficiency consideration

Now when I'm developing and I know the server has to handle each request for about 100s ~ 200s, at the merce of your suggestions and all above. The rule are here (1) idletimeout < keepalive_timeout(90s). Why? Beacuse if idletimeout > keepalive_timeout, it will occasionally occur EOFException/EofException due to the nginx's unilateral discconnect. Just like the situation I mentioned at the beginning of this issue. (2) (100s ~ 200s) < totalTimeout < proxy_read_timeout(500s)

So I can only set the jetty timeout like this: idletimeout=75s totalTimeout=210s As a result, every time I send a request, I will acctually get a TIMEOUTEXCEPTION of 75s(idletimeout). "totalTimeout" don't work. But if set the "idletimeout" larger, it will cause EOF sometimes.

zhaowenxishi commented 4 years ago

By the way, your suggestion to set the idletimeout to 75s works well temporarily. The client-end service has run two days without any EOF. I will keep observing the service. So this also proves that it's important to set idletimeout(jetty) smaller than keepalive_timeout(nginx) or some other timeout of interaction such as the "client_header_timeout" I mentioned above.

sbordet commented 4 years ago

I know the server has to handle each request for about 100s ~ 200s

That is your problem.

You cannot expect the server to go silent for 100-200 seconds when the client idle timeout is 75 seconds.

You must adjust all your timeouts so that the client timeouts are less than the server timeouts, both in the Jetty client and in the proxy.

But IMHO you have to solve the issue of a single request taking 200 seconds, as that seems an incredible large amount of time.

If you have such long computations, you don't typically use HTTP, but instead messaging systems that notifies you when a computation is finished.

stale[bot] commented 3 years ago

This issue has been automatically marked as stale because it has been a full year without activity. It will be closed if no further activity occurs. Thank you for your contributions.

sbordet commented 3 years ago

Closing, not a Jetty issue.

wei8jie commented 5 months ago

It seems that the jetty doest not remove the connection from the pool when the connection is closed by the server side. Jetty reuse the connection closed by the server side for the new request, then cause the EOF error and remove the connection from the pool. Why jetty does not maintain the TCP connection state?

sbordet commented 5 months ago

@wei8jie what you said in the comment above is not accurate: Jetty does remove the connection from the pool when closed by the server. We have tests for that specific behavior.

This issue is closed, and apparently not related to your comment.

Please open a new issue, attach a reproducer and as much information you can.