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

Requests are getting Idle Timeout #3662

Closed knoxxs closed 5 years ago

knoxxs commented 5 years ago

Hi Guys, We recently shifted our cloud environment from GCloud to AWS and suddenly some requests to our Jetty server are getting stalled. The behavior is random.

We have been digging deep to understand what is happening to such requests. Here is the analysis we have done:

Example calls

We will be focusing on two rest calls. One which is working fine and one which is getting timed out.

Call 1: Pricing

Call 2: Property

Screenshot 2019-05-15 at 6 47 48 PM

-

Screenshot 2019-05-15 at 6 47 51 PM

-

Screenshot 2019-05-15 at 6 47 58 PM

Some more info

Logs:

We switched on Debug level logs on the jetty to find more. Below are some of the statements selected from the logs (#TLDR). You can find the complete logs here.

Call 1: Pricing

2019-05-15 13:14:43.824:DBUG:oejs.HttpConnection:qtp1018081122-17: New HTTP Connection HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}-><null>
2019-05-15 13:14:43.824:DBUG:oeji.AbstractEndPoint:qtp1018081122-17: onOpen SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:43.824:DBUG:oeji.AbstractConnection:qtp1018081122-17: onOpen HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:43.824:DBUG:oeji.AbstractConnection:qtp1018081122-17: fillInterested HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:43.824:DBUG:oeji.FillInterest:qtp1018081122-17: interested FillInterest@6aca877c{AC.ReadCB@111d1138{HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}}}
2019-05-15 13:14:43.824:DBUG:oeji.ChannelEndPoint:qtp1018081122-17: changeInterests p=false 0->1 for SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=0/40000}{io=0/1,kio=0,kro=0}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:43.824:DBUG:oeji.ManagedSelector:qtp1018081122-17: Created SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=0/40000}{io=0/1,kio=0,kro=0}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:43.824:DBUG:oeji.ChannelEndPoint:qtp1018081122-8: Key interests updated 0 -> 1 on SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=0/40000}{io=1/1,kio=1,kro=0}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:44.129:DBUG:oeji.ManagedSelector:qtp1018081122-16: selected 1 sun.nio.ch.SelectionKeyImpl@26fb704 SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=305/40000}{io=1/1,kio=1,kro=1}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0} 
2019-05-15 13:14:44.129:DBUG:oeji.ChannelEndPoint:qtp1018081122-16: onSelected 1->0 r=true w=false for SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=305/40000}{io=1/0,kio=1,kro=1}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:44.129:DBUG:oeji.ChannelEndPoint:qtp1018081122-16: task CEP:SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=305/40000}{io=1/0,kio=1,kro=1}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING
2019-05-15 13:14:44.129:DBUG:oejuts.EatWhatYouKill:qtp1018081122-16: EatWhatYouKill@15cba6dc/SelectorProducer@4ac7f844/IDLE/p=true/QueuedThreadPool[qtp1018081122]@3caeaf62{STARTED,10<=10<=200,i=6,q=0}[ReservedThreadExecutor@6f7fd0e6{s=1/2,p=0}][pc=0,pic=0,pec=1,epc=1735]@2019-05-15T13:14:44.129Z m=EXECUTE_PRODUCE_CONSUME t=CEP:SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=305/40000}{io=1/0,kio=1,kro=1}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING/BLOCKING
2019-05-15 13:14:44.129:DBUG:oeji.FillInterest:qtp1018081122-16: fillable FillInterest@6aca877c{AC.ReadCB@111d1138{HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=305/40000}{io=1/0,kio=1,kro=1}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}}}
2019-05-15 13:14:44.130:DBUG:oeji.ChannelEndPoint:qtp1018081122-8: Key interests updated 1 -> 0 on SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=306/40000}{io=0/0,kio=0,kro=1}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:44.130:DBUG:oejs.HttpConnection:qtp1018081122-16: HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=306/40000}{io=0/0,kio=0,kro=1}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0} onFillable enter HttpChannelState@42b8cf5f{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} null
2019-05-15 13:14:44.130:DBUG:oeji.ChannelEndPoint:qtp1018081122-16: filled 561 SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=306/40000}{io=0/0,kio=0,kro=1}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:44.130:DBUG:oejs.HttpConnection:qtp1018081122-16: HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=1}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0} filled 561 HeapByteBuffer@68139280[p=0,l=561,c=8192,r=561]={<<<OPTIONS /rest/pan...US,en;q=0.9\r\n\r\n>>>556864897913.2473...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2019-05-15 13:14:44.130:DBUG:oejs.HttpConnection:qtp1018081122-16: HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=1}->HttpConnection@111d1138[p=HttpParser{s=START,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=0,c=false,a=IDLE,uri=null,age=0} parse HeapByteBuffer@68139280[p=0,l=561,c=8192,r=561]={<<<OPTIONS /rest/pan...US,en;q=0.9\r\n\r\n>>>556864897913.2473...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {}
2019-05-15 13:14:44.130:DBUG:oejs.HttpConnection:qtp1018081122-16: HttpConnection@111d1138[p=HttpParser{s=END,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=1,c=false,a=IDLE,uri=//app-api-aapa.morph.ai/rest/panel/pricing/search,age=0}<-SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=1}->HttpConnection@111d1138[p=HttpParser{s=END,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=1,c=false,a=IDLE,uri=//app-api-aapa.morph.ai/rest/panel/pricing/search,age=0} parsed true HttpParser{s=END,0 of -1}
2019-05-15 13:14:44.130:DBUG:oejs.HttpConnection:qtp1018081122-16: releaseRequestBuffer HttpConnection@111d1138[p=HttpParser{s=END,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=1,c=false,a=IDLE,uri=//app-api-aapa.morph.ai/rest/panel/pricing/search,age=0}<-SocketChannelEndPoint@5300ebdb{/180.151.25.131:52613<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=1}->HttpConnection@111d1138[p=HttpParser{s=END,0 of -1},g=HttpGenerator@45977ef3{s=START}]=>HttpChannelOverHttp@74eb632e{r=1,c=false,a=IDLE,uri=//app-api-aapa.morph.ai/rest/panel/pricing/search,age=1}

Call 2: Property (TimedOut)

2019-05-15 13:14:44.102:DBUG:oejs.HttpConnection:qtp1018081122-12: New HTTP Connection HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}-><null>
2019-05-15 13:14:44.102:DBUG:oeji.AbstractEndPoint:qtp1018081122-12: onOpen SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:44.102:DBUG:oeji.AbstractConnection:qtp1018081122-12: onOpen HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:44.102:DBUG:oeji.AbstractConnection:qtp1018081122-12: fillInterested HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:44.102:DBUG:oeji.FillInterest:qtp1018081122-12: interested FillInterest@4fe3c59e{AC.ReadCB@23f87840{HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}}}
2019-05-15 13:14:44.102:DBUG:oeji.ChannelEndPoint:qtp1018081122-12: changeInterests p=false 0->1 for SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=0/40000}{io=0/1,kio=0,kro=0}->HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:44.102:DBUG:oeji.ManagedSelector:qtp1018081122-12: Created SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=0/40000}{io=0/1,kio=0,kro=0}->HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:14:44.102:DBUG:oeji.ChannelEndPoint:qtp1018081122-16: Key interests updated 0 -> 1 on SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=0/40000}{io=1/1,kio=1,kro=0}->HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}

2019-05-15 13:15:24.102:DBUG:oeji.IdleTimeout:Scheduler-717356484: SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=40000/40000}{io=1/1,kio=1,kro=0}->HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} idle timeout check, elapsed: 40000 ms, remaining: 0 ms
2019-05-15 13:15:24.102:DBUG:oeji.IdleTimeout:Scheduler-717356484: SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=40000/40000}{io=1/1,kio=1,kro=0}->HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} idle timeout expired
2019-05-15 13:15:24.102:DBUG:oeji.FillInterest:Scheduler-717356484: onFail FillInterest@4fe3c59e{AC.ReadCB@23f87840{HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=40000/40000}{io=1/1,kio=1,kro=0}->HttpConnection@23f87840[p=HttpParser{s=START,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}}}
2019-05-15 13:15:24.102:DBUG:oeji.AbstractConnection:Scheduler-717356484: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=40000/40000}{io=1/1,kio=1,kro=0}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} onFillInterestedFailed java.util.concurrent.TimeoutException: Idle timeout expired: 40000/40000 ms
2019-05-15 13:15:24.102:DBUG:oeji.AbstractEndPoint:Scheduler-717356484: shutdownOutput SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=40000/40000}{io=1/1,kio=1,kro=0}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.102:DBUG:oeji.AbstractConnection:Scheduler-717356484: fillInterested HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=40000/40000}{io=1/1,kio=1,kro=0}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.102:DBUG:oeji.FillInterest:Scheduler-717356484: interested FillInterest@4fe3c59e{AC.ReadCB@23f87840{HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=1/40000}{io=1/1,kio=1,kro=0}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}}}
2019-05-15 13:15:24.103:DBUG:oeji.ChannelEndPoint:Scheduler-717356484: changeInterests p=false 1->1 for SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=1/40000}{io=1/1,kio=1,kro=0}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.103:DBUG:oeji.AbstractEndPoint:Scheduler-717356484: Ignored idle endpoint SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=1/40000}{io=1/1,kio=1,kro=0}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.103:DBUG:oeji.ChannelEndPoint:qtp1018081122-13: Key interests updated 1 -> 1 on SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=0/40000}{io=1/1,kio=1,kro=0}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.103:DBUG:oeji.ManagedSelector:qtp1018081122-13: selected 1 sun.nio.ch.SelectionKeyImpl@432f5123 SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=0/40000}{io=1/1,kio=1,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} 
2019-05-15 13:15:24.103:DBUG:oeji.ChannelEndPoint:qtp1018081122-13: onSelected 1->0 r=true w=false for SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=0/40000}{io=1/0,kio=1,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.103:DBUG:oeji.ChannelEndPoint:qtp1018081122-13: task CEP:SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=0/40000}{io=1/0,kio=1,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING
2019-05-15 13:15:24.103:DBUG:oejuts.EatWhatYouKill:qtp1018081122-13: EatWhatYouKill@15cba6dc/SelectorProducer@4ac7f844/IDLE/p=true/QueuedThreadPool[qtp1018081122]@3caeaf62{STARTED,10<=10<=200,i=6,q=0}[ReservedThreadExecutor@6f7fd0e6{s=1/2,p=0}][pc=0,pic=0,pec=1,epc=1868]@2019-05-15T13:15:24.103Z m=EXECUTE_PRODUCE_CONSUME t=CEP:SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=0/40000}{io=1/0,kio=1,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING/BLOCKING
2019-05-15 13:15:24.103:DBUG:oeji.FillInterest:qtp1018081122-13: fillable FillInterest@4fe3c59e{AC.ReadCB@23f87840{HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=0/40000}{io=0/0,kio=1,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}}}
2019-05-15 13:15:24.103:DBUG:oeji.ChannelEndPoint:qtp1018081122-8: Key interests updated 1 -> 0 on SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=0/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.103:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} onFillable enter HttpChannelState@31295789{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} null
2019-05-15 13:15:24.103:DBUG:oeji.ChannelEndPoint:qtp1018081122-13: filled 565 SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.103:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} filled 565 HeapByteBuffer@68139280[p=0,l=565,c=8192,r=565]={<<<OPTIONS /rest/pan...US,en;q=0.9\r\n\r\n>>>p=fb.1.1556864897...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2019-05-15 13:15:24.103:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} parse HeapByteBuffer@68139280[p=0,l=565,c=8192,r=565]={<<<OPTIONS /rest/pan...US,en;q=0.9\r\n\r\n>>>p=fb.1.1556864897...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {}
2019-05-15 13:15:24.104:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=1/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} parsed false HttpParser{s=CLOSE,0 of -1}
2019-05-15 13:15:24.104:DBUG:oejs.HttpConnection:qtp1018081122-13: releaseRequestBuffer HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=1/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.104:DBUG:oeji.ChannelEndPoint:qtp1018081122-13: filled 0 SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=1/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.104:DBUG:oeji.ChannelEndPoint:qtp1018081122-13: filled 0 SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=1/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.104:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=1/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} filled 0 HeapByteBuffer@68139280[p=0,l=0,c=8192,r=0]={<<<>>>OPTIONS /rest/pan...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2019-05-15 13:15:24.104:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=1/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} parse HeapByteBuffer@68139280[p=0,l=0,c=8192,r=0]={<<<>>>OPTIONS /rest/pan...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {}
2019-05-15 13:15:24.104:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=1/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} parsed false HttpParser{s=CLOSE,0 of -1}
2019-05-15 13:15:24.104:DBUG:oejs.HttpConnection:qtp1018081122-13: releaseRequestBuffer HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=1/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.104:DBUG:oeji.AbstractConnection:qtp1018081122-13: fillInterested HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=1/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.104:DBUG:oeji.FillInterest:qtp1018081122-13: interested FillInterest@4fe3c59e{AC.ReadCB@23f87840{HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=0/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}}}
2019-05-15 13:15:24.104:DBUG:oeji.ChannelEndPoint:qtp1018081122-13: changeInterests p=false 0->1 for SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=0/40000}{io=0/1,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.104:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=0/40000}{io=0/1,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} onFillable exit HttpChannelState@31295789{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} null
2019-05-15 13:15:24.104:DBUG:oeji.ChannelEndPoint:qtp1018081122-8: Key interests updated 0 -> 1 on SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=0/40000}{io=1/1,kio=1,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.527:DBUG:oeji.ManagedSelector:qtp1018081122-13: selected 1 sun.nio.ch.SelectionKeyImpl@432f5123 SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=423/40000}{io=1/1,kio=1,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} 
2019-05-15 13:15:24.527:DBUG:oeji.ChannelEndPoint:qtp1018081122-13: onSelected 1->0 r=true w=false for SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=423/40000}{io=1/0,kio=1,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.527:DBUG:oeji.ChannelEndPoint:qtp1018081122-13: task CEP:SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=423/40000}{io=1/0,kio=1,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING
2019-05-15 13:15:24.527:DBUG:oejuts.EatWhatYouKill:qtp1018081122-13: EatWhatYouKill@15cba6dc/SelectorProducer@4ac7f844/IDLE/p=true/QueuedThreadPool[qtp1018081122]@3caeaf62{STARTED,10<=10<=200,i=6,q=0}[ReservedThreadExecutor@6f7fd0e6{s=1/2,p=0}][pc=0,pic=0,pec=1,epc=1870]@2019-05-15T13:15:24.527Z m=EXECUTE_PRODUCE_CONSUME t=CEP:SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=423/40000}{io=1/0,kio=1,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING/BLOCKING
2019-05-15 13:15:24.527:DBUG:oeji.FillInterest:qtp1018081122-13: fillable FillInterest@4fe3c59e{AC.ReadCB@23f87840{HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=424/40000}{io=1/0,kio=1,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}}}
2019-05-15 13:15:24.528:DBUG:oeji.ChannelEndPoint:qtp1018081122-8: Key interests updated 1 -> 0 on SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=FI,flush=-,to=424/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.528:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=424/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} onFillable enter HttpChannelState@31295789{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} null
2019-05-15 13:15:24.528:DBUG:oeji.ChannelEndPoint:qtp1018081122-13: filled -1 SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=424/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.528:DBUG:oeji.AbstractEndPoint:qtp1018081122-13: shutdownInput SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,OSHUT,fill=-,flush=-,to=424/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.528:DBUG:oeji.ChannelEndPoint:qtp1018081122-13: doClose SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,CLOSED,fill=-,flush=-,to=424/40000}{io=0/0,kio=0,kro=1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.528:DBUG:oeji.ManagedSelector:qtp1018081122-16: Destroyed SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,CLOSED,fill=-,flush=-,to=424/40000}{io=0/0,kio=-1,kro=-1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.528:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,CLOSED,fill=-,flush=-,to=424/40000}{io=0/0,kio=-1,kro=-1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} filled -1 HeapByteBuffer@68139280[p=0,l=0,c=8192,r=0]={<<<>>>OPTIONS /rest/pan...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2019-05-15 13:15:24.528:DBUG:oeji.AbstractEndPoint:qtp1018081122-13: close SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,CLOSED,fill=-,flush=-,to=424/40000}{io=0/0,kio=-1,kro=-1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.528:DBUG:oeji.AbstractConnection:qtp1018081122-16: onClose HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,CLOSED,fill=-,flush=-,to=424/40000}{io=0/0,kio=-1,kro=-1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.528:DBUG:oeji.AbstractEndPoint:qtp1018081122-13: close(null) SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,CLOSED,fill=-,flush=-,to=424/40000}{io=0/0,kio=-1,kro=-1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.528:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,CLOSED,fill=-,flush=-,to=424/40000}{io=0/0,kio=-1,kro=-1}->HttpConnection@23f87840[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} parse HeapByteBuffer@68139280[p=0,l=0,c=8192,r=0]={<<<>>>OPTIONS /rest/pan...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {}
2019-05-15 13:15:24.528:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,CLOSED,fill=-,flush=-,to=424/40000}{io=0/0,kio=-1,kro=-1}->HttpConnection@23f87840[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} parsed false HttpParser{s=CLOSED,0 of -1}
2019-05-15 13:15:24.528:DBUG:oejs.HttpConnection:qtp1018081122-13: releaseRequestBuffer HttpConnection@23f87840[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,CLOSED,fill=-,flush=-,to=424/40000}{io=0/0,kio=-1,kro=-1}->HttpConnection@23f87840[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}
2019-05-15 13:15:24.528:DBUG:oejs.HttpConnection:qtp1018081122-13: HttpConnection@23f87840[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@3d2947b2{/180.151.25.131:52614<->/10.128.0.65:8080,CLOSED,fill=-,flush=-,to=424/40000}{io=0/0,kio=-1,kro=-1}->HttpConnection@23f87840[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@549bbf5a{s=START}]=>HttpChannelOverHttp@767db3c4{r=0,c=false,a=IDLE,uri=null,age=0} onFillable exit HttpChannelState@31295789{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} null

Analysis

Can you help me understand what is happening to Call 2? I am unable to make sense of it following the jetty architecture doc. What should I do to find more?

Also here are some more possible questions I have explored:

gregw commented 5 years ago

Looking at the failed trace we can see that a connection is accepted and onOpen called, it then registers for fillInterest, but it appears that no request was ever actually send? It looks like a request is never actually sent by the client.

Can you get a wireshark trace or tcpdump to see of the rest client is actually sending a request.

ghost commented 5 years ago

jetty.log wireshark_capture.txt

@gregw Please find the attached jetty logs along with the wireshark capture. Request path: /rest/panel/property/search/all It was sent at: 2019-06-11T07:47:10.200Z (As per the HAR value)

image

It got stalled for approximately 40 seconds. As per the wireshark capture the call was sent to server, but never completed and was idle timed out (as per the jetty logs).

HAR value for the request in question

{
  "startedDateTime": "2019-06-11T07:47:10.200Z",
  "time": 39702.27700000396,
  "request": {
    "method": "OPTIONS",
    "url": "https://app-api-aapa.morph.ai/rest/panel/property/search/all",
    "httpVersion": "http/1.1",
    "headers": [
      {
        "name": "Access-Control-Request-Method",
        "value": "GET"
      },
      {
        "name": "Origin",
        "value": "https://app.morph.ai"
      },
      {
        "name": "Referer",
        "value": "https://app.morph.ai/"
      },
      {
        "name": "User-Agent",
        "value": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36"
      },
      {
        "name": "Access-Control-Request-Headers",
        "value": "content-type"
      }
    ],
    "queryString": [],
    "cookies": [],
    "headersSize": -1,
    "bodySize": 0
  },
  "response": {
    "status": 200,
    "statusText": "OK",
    "httpVersion": "http/1.1",
    "headers": [
      {
        "name": "Access-Control-Allow-Origin",
        "value": "https://app.morph.ai"
      },
      {
        "name": "Access-Control-Allow-Credentials",
        "value": "true"
      },
      {
        "name": "Server",
        "value": "Jetty(9.4.11.v20180605)"
      },
      {
        "name": "Access-Control-Allow-Headers",
        "value": "X-Requested-With,Content-Type,Accept,Origin"
      },
      {
        "name": "Content-Length",
        "value": "0"
      },
      {
        "name": "Access-Control-Max-Age",
        "value": "1800"
      },
      {
        "name": "Access-Control-Allow-Methods",
        "value": "GET,POST,DELETE,PUT,HEAD"
      }
    ],
    "cookies": [],
    "content": {
      "size": 0,
      "mimeType": "text/plain"
    },
    "redirectURL": "",
    "headersSize": -1,
    "bodySize": -1,
    "_transferSize": 323
  },
  "cache": {},
  "timings": {
    "blocked": 39410.61600002552,
    "dns": -1,
    "ssl": -1,
    "connect": -1,
    "send": 0.09799999999813735,
    "wait": 291.15600002255815,
    "receive": 0.4069999558851123,
    "_blocked_queueing": 1.1500000255182385
  },
  "serverIPAddress": "54.186.91.81",
  "_initiator": {
    "type": "script",
    "stack": {
      "callFrames": [
        {
          "functionName": "",
          "scriptId": "10685",
          "url": "",
          "lineNumber": 0,
          "columnNumber": 780
        },
        {
          "functionName": "",
          "scriptId": "10701",
          "url": "https://app.morph.ai/main.js?v=1560147398443",
          "lineNumber": 99896,
          "columnNumber": 12574
        },
        {
          "functionName": "send",
          "scriptId": "10701",
          "url": "https://app.morph.ai/main.js?v=1560147398443",
          "lineNumber": 25929,
          "columnNumber": 28
        },
        {
          "functionName": "ajax",
          "scriptId": "10701",
          "url": "https://app.morph.ai/main.js?v=1560147398443",
          "lineNumber": 25466,
          "columnNumber": 30
        },
        {
          "functionName": "get",
          "scriptId": "10701",
          "url": "https://app.morph.ai/main.js?v=1560147398443",
          "lineNumber": 71868,
          "columnNumber": 25
        },
        {
          "functionName": "getProperties",
          "scriptId": "10701",
          "url": "https://app.morph.ai/main.js?v=1560147398443",
          "lineNumber": 72782,
          "columnNumber": 28
        },
        {
          "functionName": "sync",
          "scriptId": "10701",
          "url": "https://app.morph.ai/main.js?v=1560147398443",
          "lineNumber": 72948,
          "columnNumber": 31
        },
        {
          "functionName": "",
          "scriptId": "10714",
          "url": "https://app.morph.ai/app/altWorkspace.js?v=1560147398443",
          "lineNumber": 0,
          "columnNumber": 3445127
        },
        {
          "functionName": "fire",
          "scriptId": "10701",
          "url": "https://app.morph.ai/main.js?v=1560147398443",
          "lineNumber": 20411,
          "columnNumber": 42
        },
        {
          "functionName": "fireWith",
          "scriptId": "10701",
          "url": "https://app.morph.ai/main.js?v=1560147398443",
          "lineNumber": 20523,
          "columnNumber": 28
        },
        {
          "functionName": "done",
          "scriptId": "10701",
          "url": "https://app.morph.ai/main.js?v=1560147398443",
          "lineNumber": 25564,
          "columnNumber": 29
        },
        {
          "functionName": "",
          "scriptId": "10701",
          "url": "https://app.morph.ai/main.js?v=1560147398443",
          "lineNumber": 25904,
          "columnNumber": 36
        },
        {
          "functionName": "d",
          "scriptId": "10701",
          "url": "https://app.morph.ai/main.js?v=1560147398443",
          "lineNumber": 99896,
          "columnNumber": 6229
        }
      ],
      "parent": {
        "description": "load",
        "callFrames": [
          {
            "functionName": "v",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 99896,
            "columnNumber": 4428
          },
          {
            "functionName": "a",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 99896,
            "columnNumber": 11856
          },
          {
            "functionName": "",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 99896,
            "columnNumber": 12418
          },
          {
            "functionName": "send",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 25929,
            "columnNumber": 28
          },
          {
            "functionName": "ajax",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 25466,
            "columnNumber": 30
          },
          {
            "functionName": "post",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 71885,
            "columnNumber": 25
          },
          {
            "functionName": "getPricing",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 71953,
            "columnNumber": 28
          },
          {
            "functionName": "onRender",
            "scriptId": "10714",
            "url": "https://app.morph.ai/app/altWorkspace.js?v=1560147398443",
            "lineNumber": 0,
            "columnNumber": 3443216
          },
          {
            "functionName": "",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 30648,
            "columnNumber": 32
          },
          {
            "functionName": "triggerMethod",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 31890,
            "columnNumber": 33
          },
          {
            "functionName": "render",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 32048,
            "columnNumber": 17
          },
          {
            "functionName": "render",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 33011,
            "columnNumber": 56
          },
          {
            "functionName": "x",
            "scriptId": "10714",
            "url": "https://app.morph.ai/app/altWorkspace.js?v=1560147398443",
            "lineNumber": 0,
            "columnNumber": 3449435
          },
          {
            "functionName": "onRender",
            "scriptId": "10714",
            "url": "https://app.morph.ai/app/altWorkspace.js?v=1560147398443",
            "lineNumber": 0,
            "columnNumber": 3450548
          },
          {
            "functionName": "wrapper",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 5191,
            "columnNumber": 26
          },
          {
            "functionName": "",
            "scriptId": "10714",
            "url": "https://app.morph.ai/app/altWorkspace.js?v=1560147398443",
            "lineNumber": 0,
            "columnNumber": 1630
          },
          {
            "functionName": "apply",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 718,
            "columnNumber": 32
          },
          {
            "functionName": "wrapper",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 5579,
            "columnNumber": 23
          },
          {
            "functionName": "",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 100065,
            "columnNumber": 25
          },
          {
            "functionName": "execCb",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1688,
            "columnNumber": 32
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 863,
            "columnNumber": 50
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1138,
            "columnNumber": 33
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 129,
            "columnNumber": 22
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1188,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "emit",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1187,
            "columnNumber": 16
          },
          {
            "functionName": "check",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 938,
            "columnNumber": 29
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 623,
            "columnNumber": 32
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 625,
            "columnNumber": 28
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "breakCycle",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 612,
            "columnNumber": 16
          },
          {
            "functionName": "",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 699,
            "columnNumber": 20
          },
          {
            "functionName": "each",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 54,
            "columnNumber": 30
          },
          {
            "functionName": "checkLoaded",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 698,
            "columnNumber": 16
          },
          {
            "functionName": "completeLoad",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1606,
            "columnNumber": 16
          },
          {
            "functionName": "onScriptLoad",
            "scriptId": "10696",
            "url": "https://app.morph.ai/libs/require.js",
            "lineNumber": 1709,
            "columnNumber": 28
          },
          {
            "functionName": "d",
            "scriptId": "10701",
            "url": "https://app.morph.ai/main.js?v=1560147398443",
            "lineNumber": 99896,
            "columnNumber": 6229
          }
        ],
        "parent": {
          "description": "load",
          "callFrames": [
            {
              "functionName": "",
              "scriptId": "10701",
              "url": "https://app.morph.ai/main.js?v=1560147398443",
              "lineNumber": 99896,
              "columnNumber": 10831
            },
            {
              "functionName": "req.load",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 1937,
              "columnNumber": 21
            },
            {
              "functionName": "load",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 1677,
              "columnNumber": 20
            },
            {
              "functionName": "load",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 827,
              "columnNumber": 28
            },
            {
              "functionName": "fetch",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 817,
              "columnNumber": 65
            },
            {
              "functionName": "check",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 849,
              "columnNumber": 29
            },
            {
              "functionName": "enable",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 1175,
              "columnNumber": 21
            },
            {
              "functionName": "enable",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 1548,
              "columnNumber": 38
            },
            {
              "functionName": "",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 1160,
              "columnNumber": 32
            },
            {
              "functionName": "",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 129,
              "columnNumber": 22
            },
            {
              "functionName": "each",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 54,
              "columnNumber": 30
            },
            {
              "functionName": "enable",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 1112,
              "columnNumber": 16
            },
            {
              "functionName": "init",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 781,
              "columnNumber": 25
            },
            {
              "functionName": "",
              "scriptId": "10696",
              "url": "https://app.morph.ai/libs/require.js",
              "lineNumber": 1451,
              "columnNumber": 35
            },
            {
              "functionName": "d",
              "scriptId": "10701",
              "url": "https://app.morph.ai/main.js?v=1560147398443",
              "lineNumber": 99896,
              "columnNumber": 6229
            }
          ],
          "parent": {
            "description": "setTimeout",
            "callFrames": [
              {
                "functionName": "",
                "scriptId": "10701",
                "url": "https://app.morph.ai/main.js?v=1560147398443",
                "lineNumber": 99896,
                "columnNumber": 10405
              },
              {
                "functionName": "req.nextTick",
                "scriptId": "10696",
                "url": "https://app.morph.ai/libs/require.js",
                "lineNumber": 1807,
                "columnNumber": 8
              },
              {
                "functionName": "localRequire",
                "scriptId": "10696",
                "url": "https://app.morph.ai/libs/require.js",
                "lineNumber": 1440,
                "columnNumber": 28
              },
              {
                "functionName": "requirejs",
                "scriptId": "10696",
                "url": "https://app.morph.ai/libs/require.js",
                "lineNumber": 1789,
                "columnNumber": 23
              },
              {
                "functionName": "",
                "scriptId": "10701",
                "url": "https://app.morph.ai/main.js?v=1560147398443",
                "lineNumber": 100061,
                "columnNumber": 12
              },
              {
                "functionName": "triggerEvents",
                "scriptId": "10701",
                "url": "https://app.morph.ai/main.js?v=1560147398443",
                "lineNumber": 28413,
                "columnNumber": 58
              },
              {
                "functionName": "triggerApi",
                "scriptId": "10701",
                "url": "https://app.morph.ai/main.js?v=1560147398443",
                "lineNumber": 28397,
                "columnNumber": 24
              },
              {
                "functionName": "eventsApi",
                "scriptId": "10701",
                "url": "https://app.morph.ai/main.js?v=1560147398443",
                "lineNumber": 28195,
                "columnNumber": 19
              },
              {
                "functionName": "Events.trigger",
                "scriptId": "10701",
                "url": "https://app.morph.ai/main.js?v=1560147398443",
                "lineNumber": 28387,
                "columnNumber": 8
              },
              {
                "functionName": "",
                "scriptId": "10701",
                "url": "https://app.morph.ai/main.js?v=1560147398443",
                "lineNumber": 30654,
                "columnNumber": 36
              },
              {
                "functionName": "Marionette.triggerMethod",
                "scriptId": "10701",
                "url": "https://app.morph.ai/main.js?v=1560147398443",
                "lineNumber": 30672,
                "columnNumber": 26
              },
              {
                "functionName": "start",
                "scriptId": "10701",
                "url": "https://app.morph.ai/main.js?v=1560147398443",
                "lineNumber": 33498,
                "columnNumber": 17
              },
              {
                "functionName": "",
                "scriptId": "10701",
                "url": "https://app.morph.ai/main.js?v=1560147398443",
                "lineNumber": 216,
                "columnNumber": 16
              },
              {
                "functionName": "execCb",
                "scriptId": "10696",
                "url": "https://app.morph.ai/libs/require.js",
                "lineNumber": 1688,
                "columnNumber": 32
              },
              {
                "functionName": "check",
                "scriptId": "10696",
                "url": "https://app.morph.ai/libs/require.js",
                "lineNumber": 863,
                "columnNumber": 50
              },
              {
                "functionName": "enable",
                "scriptId": "10696",
                "url": "https://app.morph.ai/libs/require.js",
                "lineNumber": 1175,
                "columnNumber": 21
              },
              {
                "functionName": "init",
                "scriptId": "10696",
                "url": "https://app.morph.ai/libs/require.js",
                "lineNumber": 781,
                "columnNumber": 25
              },
              {
                "functionName": "",
                "scriptId": "10696",
                "url": "https://app.morph.ai/libs/require.js",
                "lineNumber": 1451,
                "columnNumber": 35
              }
            ],
            "parent": {
              "description": "setTimeout",
              "callFrames": [
                {
                  "functionName": "req.nextTick",
                  "scriptId": "10696",
                  "url": "https://app.morph.ai/libs/require.js",
                  "lineNumber": 1807,
                  "columnNumber": 8
                },
                {
                  "functionName": "localRequire",
                  "scriptId": "10696",
                  "url": "https://app.morph.ai/libs/require.js",
                  "lineNumber": 1440,
                  "columnNumber": 28
                },
                {
                  "functionName": "requirejs",
                  "scriptId": "10696",
                  "url": "https://app.morph.ai/libs/require.js",
                  "lineNumber": 1789,
                  "columnNumber": 23
                },
                {
                  "functionName": "",
                  "scriptId": "10701",
                  "url": "https://app.morph.ai/main.js?v=1560147398443",
                  "lineNumber": 205,
                  "columnNumber": 8
                },
                {
                  "functionName": "execCb",
                  "scriptId": "10696",
                  "url": "https://app.morph.ai/libs/require.js",
                  "lineNumber": 1688,
                  "columnNumber": 32
                },
                {
                  "functionName": "check",
                  "scriptId": "10696",
                  "url": "https://app.morph.ai/libs/require.js",
                  "lineNumber": 863,
                  "columnNumber": 50
                },
                {
                  "functionName": "enable",
                  "scriptId": "10696",
                  "url": "https://app.morph.ai/libs/require.js",
                  "lineNumber": 1175,
                  "columnNumber": 21
                },
                {
                  "functionName": "init",
                  "scriptId": "10696",
                  "url": "https://app.morph.ai/libs/require.js",
                  "lineNumber": 781,
                  "columnNumber": 25
                },
                {
                  "functionName": "",
                  "scriptId": "10696",
                  "url": "https://app.morph.ai/libs/require.js",
                  "lineNumber": 1451,
                  "columnNumber": 35
                }
              ],
              "parent": {
                "description": "setTimeout",
                "callFrames": [
                  {
                    "functionName": "req.nextTick",
                    "scriptId": "10696",
                    "url": "https://app.morph.ai/libs/require.js",
                    "lineNumber": 1807,
                    "columnNumber": 8
                  },
                  {
                    "functionName": "localRequire",
                    "scriptId": "10696",
                    "url": "https://app.morph.ai/libs/require.js",
                    "lineNumber": 1440,
                    "columnNumber": 28
                  },
                  {
                    "functionName": "requirejs",
                    "scriptId": "10696",
                    "url": "https://app.morph.ai/libs/require.js",
                    "lineNumber": 1789,
                    "columnNumber": 23
                  },
                  {
                    "functionName": "",
                    "scriptId": "10701",
                    "url": "https://app.morph.ai/main.js?v=1560147398443",
                    "lineNumber": 203,
                    "columnNumber": 4
                  },
                  {
                    "functionName": "",
                    "scriptId": "10701",
                    "url": "https://app.morph.ai/main.js?v=1560147398443",
                    "lineNumber": 220,
                    "columnNumber": 1
                  }
                ]
              }
            }
          }
        }
      }
    }
  },
  "_priority": "High",
  "_resourceType": "xhr",
  "connection": "240971",
  "pageref": "page_52"
}
gregw commented 5 years ago

Any chance of the wireshark capture file itself so I can load into wireshark myself to analyse. The info is in the text, but hard to analyse without filters etc.

ghost commented 5 years ago

@gregw Here is the link for the requested file: https://transfer.sh/spYU7/Wireshark_Capture.pcapng

sbordet commented 5 years ago

@deemorph what happens is that you are making a cross-domain call from XHR, so the browser first sends a preflight OPTIONS request to the server, as per the CORS specification. The server answers to that OPTIONS request, but the browser does not like the answer and closes the connection, never actually sending the GET request for the resource.

You need to check your CORS configuration, check what would the next GET be like (URI and headers) and see why the browser does not like the response (it is probably some missing or incorrect CORS header in the OPTIONS response).

ghost commented 5 years ago

@sbordet thanks for the response.

Yes we are using CORS but that is not the issue here. Let me explain in detail:

According to wireshark, this happened:

  1. At 07:47:10 Browser sent the Options call. To which there is no response from the server, according to wireshark.
  2. At 07:47:49.6 Browser sent the same Options request again and this time server has sent a response, which browser likes as an answers. So
  3. At 07:47:49.9 Browser sent the GET request and gets a successful response from the server.

Also, we have been using this same configuration for long and we have never got an error due to this configuration and this same OPTIONS was successful when retried, you can see the same in the wireshark capture. This is our CORS filter configuration:

<!--CORS FILTER-->
    <filter>
        <filter-name>cross-origin</filter-name>
        <filter-class>org.eclipse.jetty.servlets.CrossOriginFilter</filter-class>
        <init-param>
            <param-name>allowedOrigins</param-name>
            <param-value>*</param-value>
        </init-param>
        <init-param>
            <param-name>allowedMethods</param-name>
            <param-value>GET,POST,DELETE,PUT,HEAD</param-value>
        </init-param>
        <init-param>
            <param-name>allowedHeaders</param-name>
            <param-value>*</param-value>
        </init-param>
        <init-param>
            <param-name>chainPreflight</param-name>
            <param-value>false</param-value>
        </init-param>
    </filter>
    <filter-mapping>
        <filter-name>cross-origin</filter-name>
        <url-pattern>*</url-pattern>
    </filter-mapping>
gregw commented 5 years ago

@deemorph Moreover, the idle timeouts in the log appear to be for unrelated connections that are just correctly idling out between requests. Note how the parser is in start state:

2019-06-11 07:47:50.633:DBUG:oeji.IdleTimeout:Scheduler-717356484: SocketChannelEndPoint@5e3fa3c8{/203.122.3.45:61932<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=40000/40000}{io=1/1,kio=1,kro=1}->HttpConnection@cb08f29[p=HttpParser{s=START,0 of -1},g=HttpGenerator@2fb24c94{s=START}]=>HttpChannelOverHttp@46061bab{r=78,c=false,a=IDLE,uri=null,age=0} idle timeout expired

If you look in the log for a entries about a timedout connection (eg HttpConnection@7dd85fd) you see it handling requests and responses normally, then go idle for 40s after a valid response and then correctly timeout.

gregw commented 5 years ago

@deemorph can you point to the OPTION request that does not get a response in the jetty-log file?

gregw commented 5 years ago

I can see 5 channels in the log:

HttpChannelOverHttp@24c9af7
HttpChannelOverHttp@25ad54e2
HttpChannelOverHttp@46061bab
HttpChannelOverHttp@6104ca3a
HttpChannelOverHttp@7fabc208

and I have separated out all their logs into separate files. Currently I see all of them terminating correctly after a committed response to a request, except for HttpChannelOverHttp@25ad54e2 and HttpChannelOverHttp@6104ca3a which don't receive any requests in the log before timing out.

Note also, thanks for the wireshark file itself, but it is encrypted TLS so no use. Again, can you point out exactly in the log file or text wireshark which OPTION request you think is not receiving a response?

ghost commented 5 years ago

@gregw In the wireshark the request that is not receiving response is

No.     Time                          Source                Destination           Protocol Length Info
   4944 2019-06-11 07:47:10.202222    192.168.0.54          54.186.91.81          HTTP     604    OPTIONS /rest/panel/property/search/all HTTP/1.1 

Frame 4944: 604 bytes on wire (4832 bits), 604 bytes captured (4832 bits) on interface 0
Ethernet II, Src: Apple_ea:e9:e1 (a4:5e:60:ea:e9:e1), Dst: D-LinkIn_57:8f:ba (78:32:1b:57:8f:ba)
Internet Protocol Version 4, Src: 192.168.0.54, Dst: 54.186.91.81
Transmission Control Protocol, Src Port: 63286, Dst Port: 443, Seq: 644, Ack: 3043, Len: 538
Transport Layer Security
    TLSv1.2 Record Layer: Application Data Protocol: http-over-tls
Hypertext Transfer Protocol
    OPTIONS /rest/panel/property/search/all HTTP/1.1\r\n
        [Expert Info (Chat/Sequence): OPTIONS /rest/panel/property/search/all HTTP/1.1\r\n]
        Request Method: OPTIONS
        Request URI: /rest/panel/property/search/all
        Request Version: HTTP/1.1
    Host: app-api-aapa.morph.ai\r\n
    Connection: keep-alive\r\n
    Pragma: no-cache\r\n
    Cache-Control: no-cache\r\n
    Access-Control-Request-Method: GET\r\n
    Origin: https://app.morph.ai\r\n
    User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36\r\n
    Access-Control-Request-Headers: content-type\r\n
    Accept: */*\r\n
    Referer: https://app.morph.ai/\r\n
    Accept-Encoding: gzip, deflate, br\r\n
    Accept-Language: en-US,en;q=0.9\r\n
    \r\n
    [Full request URI: https://app-api-aapa.morph.ai/rest/panel/property/search/all]
    [HTTP request 1/1]

In jetty logs

2019-06-11 07:47:09.458:DBUG:oejs.HttpChannel:qtp1018081122-12: new HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0} -> SocketChannelEndPoint@72f92f60{/203.122.3.45:63286<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}-><null>,null,HttpChannelState@6773edb0{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false}
2019-06-11 07:47:09.458:DBUG:oejs.HttpConnection:qtp1018081122-12: New HTTP Connection HttpConnection@5c931de2[p=HttpParser{s=START,0 of -1},g=HttpGenerator@67aabb3f{s=START}]=>HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@72f92f60{/203.122.3.45:63286<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}-><null>
2019-06-11 07:47:09.458:DBUG:oeji.AbstractEndPoint:qtp1018081122-12: onOpen SocketChannelEndPoint@72f92f60{/203.122.3.45:63286<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@5c931de2[p=HttpParser{s=START,0 of -1},g=HttpGenerator@67aabb3f{s=START}]=>HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0}
2019-06-11 07:47:09.458:DBUG:oeji.AbstractConnection:qtp1018081122-12: onOpen HttpConnection@5c931de2[p=HttpParser{s=START,0 of -1},g=HttpGenerator@67aabb3f{s=START}]=>HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@72f92f60{/203.122.3.45:63286<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@5c931de2[p=HttpParser{s=START,0 of -1},g=HttpGenerator@67aabb3f{s=START}]=>HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0}
2019-06-11 07:47:09.458:DBUG:oeji.AbstractConnection:qtp1018081122-12: fillInterested HttpConnection@5c931de2[p=HttpParser{s=START,0 of -1},g=HttpGenerator@67aabb3f{s=START}]=>HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@72f92f60{/203.122.3.45:63286<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@5c931de2[p=HttpParser{s=START,0 of -1},g=HttpGenerator@67aabb3f{s=START}]=>HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0}
2019-06-11 07:47:09.458:DBUG:oeji.FillInterest:qtp1018081122-12: interested FillInterest@286fe96c{AC.ReadCB@5c931de2{HttpConnection@5c931de2[p=HttpParser{s=START,0 of -1},g=HttpGenerator@67aabb3f{s=START}]=>HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0}<-SocketChannelEndPoint@72f92f60{/203.122.3.45:63286<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}->HttpConnection@5c931de2[p=HttpParser{s=START,0 of -1},g=HttpGenerator@67aabb3f{s=START}]=>HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0}}}
ghost commented 5 years ago

@gregw Also this behavior we are only facing on chrome. Firefox and Safari are working properly. Only on chrome we are getting frequent stalled connections.

Chrome logs for the same are:

+REQUEST_ALIVE  [dt=28970]
 --> priority = "MEDIUM"
 --> url = "https://app-api.morph.ai/rest/panel/property/search/all"
   NETWORK_DELEGATE_BEFORE_URL_REQUEST  [dt=0]
  +URL_REQUEST_START_JOB  [dt=28969]
   --> load_flags = 834 (BYPASS_CACHE | DO_NOT_SAVE_COOKIES | DO_NOT_SEND_AUTH_DATA | DO_NOT_SEND_COOKIES)
   --> method = "OPTIONS"
   --> privacy_mode = 1
   --> url = "https://app-api.morph.ai/rest/panel/property/search/all"
     NETWORK_DELEGATE_BEFORE_START_TRANSACTION  [dt=0]
     HTTP_CACHE_GET_BACKEND  [dt=0]
    +HTTP_STREAM_REQUEST  [dt=1]
       HTTP_STREAM_JOB_CONTROLLER_BOUND
       --> source_dependency = 433404 (HTTP_STREAM_JOB_CONTROLLER)
       HTTP_STREAM_REQUEST_BOUND_TO_JOB
       --> source_dependency = 433405 (HTTP_STREAM_JOB)
    -HTTP_STREAM_REQUEST
    +HTTP_TRANSACTION_SEND_REQUEST  [dt=0]
       HTTP_TRANSACTION_SEND_REQUEST_HEADERS
       --> OPTIONS /rest/panel/property/search/all HTTP/1.1
           Host: app-api.morph.ai
           Connection: keep-alive
           Pragma: no-cache
           Cache-Control: no-cache
           Access-Control-Request-Method: GET
           Origin: https://app.morph.ai
           User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36
           Access-Control-Request-Headers: content-type
           Accept: */*
           Referer: https://app.morph.ai/
           Accept-Encoding: gzip, deflate, br
           Accept-Language: en-US,en;q=0.9
    -HTTP_TRANSACTION_SEND_REQUEST
    +HTTP_TRANSACTION_READ_HEADERS  [dt=28675]
       HTTP_STREAM_PARSER_READ_HEADERS  [dt=28674]
       --> net_error = -324 (ERR_EMPTY_RESPONSE)
       HTTP_TRANSACTION_RESTART_AFTER_ERROR
       --> net_error = -324 (ERR_EMPTY_RESPONSE)
    -HTTP_TRANSACTION_READ_HEADERS
    +HTTP_STREAM_REQUEST  [dt=0]
       HTTP_STREAM_JOB_CONTROLLER_BOUND
       --> source_dependency = 433595 (HTTP_STREAM_JOB_CONTROLLER)
       HTTP_STREAM_REQUEST_BOUND_TO_JOB
       --> source_dependency = 433596 (HTTP_STREAM_JOB)
    -HTTP_STREAM_REQUEST
    +HTTP_TRANSACTION_SEND_REQUEST  [dt=0]
       HTTP_TRANSACTION_SEND_REQUEST_HEADERS
       --> OPTIONS /rest/panel/property/search/all HTTP/1.1
           Host: app-api.morph.ai
           Connection: keep-alive
           Pragma: no-cache
           Cache-Control: no-cache
           Access-Control-Request-Method: GET
           Origin: https://app.morph.ai
           User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36
           Access-Control-Request-Headers: content-type
           Accept: */*
           Referer: https://app.morph.ai/
           Accept-Encoding: gzip, deflate, br
           Accept-Language: en-US,en;q=0.9
    -HTTP_TRANSACTION_SEND_REQUEST
    +HTTP_TRANSACTION_READ_HEADERS  [dt=293]
       HTTP_STREAM_PARSER_READ_HEADERS  [dt=293]
       HTTP_TRANSACTION_READ_RESPONSE_HEADERS
       --> HTTP/1.1 200 OK
           Access-Control-Allow-Origin: https://app.morph.ai
           Access-Control-Allow-Credentials: true
           Access-Control-Max-Age: 1800
           Access-Control-Allow-Methods: GET,POST,DELETE,PUT,HEAD
           Access-Control-Allow-Headers: X-Requested-With,Content-Type,Accept,Origin
           Content-Length: 0
           Server: Jetty(9.4.18.v20190429)
    -HTTP_TRANSACTION_READ_HEADERS
     NETWORK_DELEGATE_HEADERS_RECEIVED  [dt=0]
  -URL_REQUEST_START_JOB
   URL_REQUEST_DELEGATE_RESPONSE_STARTED  [dt=0]
   HTTP_TRANSACTION_READ_BODY  [dt=0]
-REQUEST_ALIVE
gregw commented 5 years ago

@deemorph what is doing your TLS decoding as it looks like the request is being lost there! Probably some AWS magic??

You can see in the wireshark that it was sent from/to:

Internet Protocol Version 4, Src: 192.168.0.54, Dst: 54.186.91.81
Transmission Control Protocol, Src Port: 63286, Dst Port: 443, Seq: 644, Ack: 3043, Len: 538

But jetty is not listening to 443, it is listening to 8080. It does see a connection:

2019-06-11 07:47:09.458:DBUG:oejs.HttpChannel:qtp1018081122-12: new HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0} -> SocketChannelEndPoint@72f92f60{/203.122.3.45:63286<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}-><null>,null,HttpChannelState@6773edb0{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false}

Strangely enough reported from same port as TLS, but a different IP (203.122.3.45 instead of 192.168.0.54). Note also that the destination IP is different (10.128.0.65 rather than 54.186.91.81).
This connection correctly transitions to being fill interested:

2019-06-11 07:47:09.459:DBUG:oeji.ChannelEndPoint:qtp1018081122-15: Key interests updated 0 -> 1 on SocketChannelEndPoint@72f92f60{/203.122.3.45:63286<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=1/40000}{io=1/1,kio=1,kro=0}->HttpConnection@5c931de2[p=HttpParser{s=START,0 of -1},g=HttpGenerator@67aabb3f{s=START}]=>HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0}

but no data ever arrives on that connection!
Without jetty reading data, it is not possible for it to treat a chrome request any differently from any other request. If it were a problem with jetty just not selecting properly, it would equally affect all browsers because at this stage it is just an TCP/IP connection.

So I'm thinking this must be an AWS problem, as there is no evidence that OPTION request is every delivered to jetty!

ghost commented 5 years ago

@gregw We are using AWS Network Load Balancer with SSL Termination. 192.168.0.54 : Local IP 203.122.3.45 : Public IP from which the request came 54.186.91.81 : AWS LB Public IP 10.128.0.65 : Instance Local IP

But the request did come to the jetty instance as per the logs ??

2019-06-11 07:47:09.458:DBUG:oejs.HttpChannel:qtp1018081122-12: new HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0} -> SocketChannelEndPoint@72f92f60{/203.122.3.45:63286<->/10.128.0.65:8080,OPEN,fill=-,flush=-,to=0/40000}{io=0/0,kio=0,kro=0}-><null>,null,HttpChannelState@6773edb0{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false}
ghost commented 5 years ago

@gregw We also checked with sysdig -pc -c httplog Request does come to the server:

host < method=OPTIONS url=app-api-aapa.morph.ai/rest/panel/property/search/all response_code=10 latency=393ms size=0B
host < method=OPTIONS url=app-api-aapa.morph.ai/rest/panel/property/search/all response_code=200 latency=0ms size=0B
host < method=GET url=app-api-aapa.morph.ai/rest/panel/property/search/all response_code=200 latency=4ms size=0B

sysdig -A -pc -c echo_fds fd.port=8080

(Failed one)
------ Read 504B from  [host] [host]  203.122.3.45:63286->10.128.0.65:8080 (java)

OPTIONS /rest/panel/property/search/all HTTP/1.1
Host: app-api-aapa.morph.ai
Connection: keep-alive
Pragma: no-cache
Cache-Control: no-cache
Access-Control-Request-Method: GET
Origin: https://app.morph.ai
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36
Access-Control-Request-Headers: content-type
Accept: */*
Referer: https://app.morph.ai/
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9

------ Read 504B from  [host] [host]  203.122.3.45:63285->10.128.0.65:8080 (java)

OPTIONS /rest/panel/property/search/all HTTP/1.1
Host: app-api-aapa.morph.ai
Connection: keep-alive
Pragma: no-cache
Cache-Control: no-cache
Access-Control-Request-Method: GET
Origin: https://app.morph.ai
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36
Access-Control-Request-Headers: content-type
Accept: */*
Referer: https://app.morph.ai/
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9

------ Read 780B from  [host] [host]  203.122.3.45:62835->10.128.0.65:8080 (java)

GET /rest/panel/property/search/all HTTP/1.1
Host: app-api-aapa.morph.ai
Connection: keep-alive
Accept: */*
Origin: https://app.morph.ai
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/75.0.3770.80 Safari/537.36
Content-Type: application/json
Referer: https://app.morph.ai/
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9
Cookie: ...
gregw commented 5 years ago

@deemorph The jetty log indicates that a connection was opened for the request, but that no data was ever received. I'm not sure what your sysdig is showing us?

Is there any evidence that any data was ever sent over the TCP/IP connection /203.122.3.45:63286<->/10.128.0.65:8080 ?

We are just not seeing anything. The last log we have when the connection is received is:

2019-06-11 07:47:09.459:DBUG:oeji.ChannelEndPoint:qtp1018081122-15: Key interests updated 0 -> 1 on SocketChannelEndPoint@72f92f60{/203.122.3.45:63286<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=1/40000}{io=1/1,kio=1,kro=0}->HttpConnection@5c931de2[p=HttpParser{s=START,0 of -1},g=HttpGenerator@67aabb3f{s=START}]=>HttpChannelOverHttp@25ad54e2{r=0,c=false,a=IDLE,uri=null,age=0}

which is the registration on the selector for READ interest. The next log for that connection is

2019-06-11 07:47:49.458:DBUG:oeji.IdleTimeout:Scheduler-717356484: SocketChannelEndPoint@72f92f60{/203.122.3.45:63286<->/10.128.0.65:8080,OPEN,fill=FI,flush=-,to=40000/40000}{io=1/1,kio=1,kro=0}

which is 40 seconds later and the start of the idle timeout. We have no activity for that connection between those two logs, but the associated selector (EPollSelectorImpl@64efc31b) is active and selecting other connections, so it does not look like a selector problem. We are just not seeing any data for that connection!

knoxxs commented 5 years ago

@gregw Yup, you are correct. @deemorph & I were digging more into it and realized the issue is in LB (load balancer) we have been using in front of the server.

Thanks for all the help, we were able to drill down to this exact issue after your help. When you cleared that the connection is coming but no data is sent after that, it really clarified a lot of our doubts. We were not able to conclude this after analyzing the jetty logs. Because the issue is in LB, everything was looking fine at the client side (as seen from Wireshark).

Thanks a lot for spending time with us on analyzing it. Really appreciate it. Also, anytime you come to India, do hit me up. Drinks are on us.

I am closing this ticket right now. If in case, I need more support on this, I will re-open.

turcsanyip commented 4 years ago

@knoxxs @deemorph We are facing a very similar issue: connection opened, some data received, then nothing happens and idle timeout occurs in the end. It affects only a few requests, the majority of the requests are being served properly in parallel. We use the same version of Jetty (9.4.11.v20180605), embedded in our app. The servers are located behind a firewall and a load balancer.

If you can recall, could you please share some details about the LB issue you had?

Any help or hint would be welcome. Thanks a lot in advance!