Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [jetty-users] HTTP 504 Gateway timeout issue
Hi Joakim,

Thanks for the quick reply, unfortunately, I'm not using the ProxyServlet and I still get an error. Looking at the logs, it seems to come from an async HTTP channel that gets terminated, but it ignores the set idleTimeout.

I've also tried explicitly setting the HttpChannelState.DEFAULT_TIMEOUT to a larger timeout with System.setProperty("org.eclipse.jetty.server.HttpChannelState.DEFAULT_TIMEOUT", "300000"),
it didn't help.

It seems that the async timeout mechanism/callback doesn't take the HttpChannel's idleTimeout value into account.

The debug log trace of the events:

2020-02-21 15:41:32 DEBUG HttpChannel:682 - REQUEST for //localhost:8081/subscriptions on HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=//localhost:8081/subscriptions,age=0}
POST //localhost:8081/subscriptions HTTP/1.1
User-Agent: PostmanRuntime/7.22.0
Accept: */*
Cache-Control: no-cache
Postman-Token: 5f7ddb6f-8021-4d0d-a875-3902641854f4
Host: localhost:8081
Accept-Encoding: gzip, deflate, br
Content-Length: 0
Connection: keep-alive


2020-02-21 15:41:32 DEBUG HttpConnection:364 - HttpConnection@15308b22::SocketChannelEndPoint@3b87331f{/0:0:0:0:0:0:0:1:53423<->/0:0:0:0:0:0:0:1:8081,OPEN,fill=-,flush=-,to=14/3000000}{io=0/0,kio=0,kro=1}->HttpConnection@15308b22[p=HttpParser{s=CONTENT,0 of 0},g=HttpGenerator@101cd798{s=START}]=>HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=//localhost:8081/subscriptions,age=1} parsed true HttpParser{s=CONTENT,0 of 0}
2020-02-21 15:41:32 DEBUG HttpConnection:220 - releaseRequestBuffer HttpConnection@15308b22::SocketChannelEndPoint@3b87331f{/0:0:0:0:0:0:0:1:53423<->/0:0:0:0:0:0:0:1:8081,OPEN,fill=-,flush=-,to=14/3000000}{io=0/0,kio=0,kro=1}->HttpConnection@15308b22[p=HttpParser{s=CONTENT,0 of 0},g=HttpGenerator@101cd798{s=START}]=>HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=//localhost:8081/subscriptions,age=2}
2020-02-21 15:41:32 DEBUG HttpChannel:344 - handle //localhost:8081/subscriptions HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=//localhost:8081/subscriptions,age=2}
2020-02-21 15:41:32 DEBUG HttpChannelState:371 - handling HttpChannelState@3ab851e6{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0}
2020-02-21 15:41:32 DEBUG HttpChannel:358 - action DISPATCH HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=//localhost:8081/subscriptions,age=3}
2020-02-21 15:41:32 DEBUG Server:483 - REQUEST POST /subscriptions on HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=//localhost:8081/subscriptions,age=5}
2020-02-21 15:41:32 DEBUG ContextHandler:1135 - scope null||/subscriptions @ o.e.j.w.WebAppContext@610694f1{/,file:///Users/salid/git/datahub-sas-loader/src/main/webapp/,AVAILABLE}
2020-02-21 15:41:32 DEBUG ContextHandler:1210 - context=||/subscriptions @ o.e.j.w.WebAppContext@610694f1{/,file:///Users/salid/git/datahub-sas-loader/src/main/webapp/,AVAILABLE}
2020-02-21 15:41:32 DEBUG session:1516 - Entering scope org.eclipse.jetty.server.session.SessionHandler1132547352==dftMaxIdleSec=1800, dispatch=REQUEST asyncstarted=false
2020-02-21 15:41:32 DEBUG session:1574 - sessionHandler=org.eclipse.jetty.server.session.SessionHandler1132547352==dftMaxIdleSec=1800 session=null
2020-02-21 15:41:32 DEBUG ServletHandler:477 - servlet ||/subscriptions -> com.alphacruncher.nuvolos.data.NuvolosDataLoaderServlet@a0dd369b==com.alphacruncher.nuvolos.data.NuvolosDataLoaderServlet,jsp=null,order=1,inst=true,async=true
2020-02-21 15:41:32 DEBUG ServletHandler:525 - chain=null
2020-02-21 15:41:32 DEBUG HttpChannelState:531 - startAsync HttpChannelState@3ab851e6{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0}
2020-02-21 15:41:32 DEBUG session:1586 - Leaving scope org.eclipse.jetty.server.session.SessionHandler1132547352==dftMaxIdleSec=1800 dispatch=REQUEST, async=true, session=null, oldsession=null, oldsessionhandler=null
2020-02-21 15:41:32 DEBUG Server:503 - handled=true async=true committed=false on HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=HANDLING rs=ASYNC os=OPEN is=IDLE awp=false se=false i=true al=1},r=1,c=false/false,a=HANDLING,uri=//localhost:8081/subscriptions,age=313}
2020-02-21 15:41:32 DEBUG HttpChannelState:413 - unhandle HttpChannelState@3ab851e6{s=HANDLING rs=ASYNC os=OPEN is=IDLE awp=false se=false i=true al=1}
2020-02-21 15:41:32 DEBUG HttpChannelState:422 - nextAction(false) WAIT HttpChannelState@3ab851e6{s=WAITING rs=ASYNC os=OPEN is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:41:32 DEBUG HttpChannel:358 - action WAIT HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=WAITING rs=ASYNC os=OPEN is=IDLE awp=false se=false i=false al=1},r=1,c=false/false,a=WAITING,uri=//localhost:8081/subscriptions,age=314}
2020-02-21 15:41:32 DEBUG HttpChannel:533 - !handle WAIT HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=WAITING rs=ASYNC os=OPEN is=IDLE awp=false se=false i=false al=1},r=1,c=false/false,a=WAITING,uri=//localhost:8081/subscriptions,age=314}
2020-02-21 15:41:32 DEBUG HttpConnection:293 - HttpConnection@15308b22::SocketChannelEndPoint@3b87331f{/0:0:0:0:0:0:0:1:53423<->/0:0:0:0:0:0:0:1:8081,OPEN,fill=-,flush=-,to=327/3000000}{io=0/0,kio=0,kro=1}->HttpConnection@15308b22[p=HttpParser{s=CONTENT,0 of 0},g=HttpGenerator@101cd798{s=START}]=>HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=WAITING rs=ASYNC os=OPEN is=IDLE awp=false se=false i=false al=1},r=1,c=false/false,a=WAITING,uri=//localhost:8081/subscriptions,age=314} onFillable exit HttpChannelState@3ab851e6{s=WAITING rs=ASYNC os=OPEN is=IDLE awp=false se=false i=false al=1} null
2020-02-21 15:41:32 DEBUG QueuedThreadPool:940 - ran CEP:SocketChannelEndPoint@3b87331f{/0:0:0:0:0:0:0:1:53423<->/0:0:0:0:0:0:0:1:8081,OPEN,fill=-,flush=-,to=327/3000000}{io=0/0,kio=0,kro=1}->HttpConnection@15308b22[p=HttpParser{s=CONTENT,0 of 0},g=HttpGenerator@101cd798{s=START}]=>HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=WAITING rs=ASYNC os=OPEN is=IDLE awp=false se=false i=false al=1},r=1,c=false/false,a=WAITING,uri=//localhost:8081/subscriptions,age=314}:runFillable:BLOCKING in QueuedThreadPool[qtp1753447031]@68837a77{STARTED,8<=10<=200,i=2,r=8,q=0}[ReservedThreadExecutor@77ec78b9{s=2/8,p=0}]
2020-02-21 15:42:02 DEBUG HttpChannelState:616 - Timeout HttpChannelState@3ab851e6{s=WAITING rs=ASYNC os=OPEN is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:42:02 DEBUG HttpChannelState:632 - Dispatch after async timeout HttpChannelState@3ab851e6{s=WOKEN rs=EXPIRE os=OPEN is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:42:02 DEBUG QueuedThreadPool:543 - queue HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=WOKEN rs=EXPIRE os=OPEN is=IDLE awp=false se=false i=false al=1},r=1,c=false/false,a=WOKEN,uri=//localhost:8081/subscriptions,age=30317} startThread=0
2020-02-21 15:42:02 DEBUG QueuedThreadPool:937 - run HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=WOKEN rs=EXPIRE os=OPEN is=IDLE awp=false se=false i=false al=1},r=1,c=false/false,a=WOKEN,uri=//localhost:8081/subscriptions,age=30317} in QueuedThreadPool[qtp1753447031]@68837a77{STARTED,8<=10<=200,i=2,r=8,q=0}[ReservedThreadExecutor@77ec78b9{s=2/8,p=0}]
2020-02-21 15:42:02 DEBUG HttpChannel:344 - handle //localhost:8081/subscriptions HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=WOKEN rs=EXPIRE os=OPEN is=IDLE awp=false se=false i=false al=1},r=1,c=false/false,a=WOKEN,uri=//localhost:8081/subscriptions,age=30318}
2020-02-21 15:42:02 DEBUG HttpChannelState:371 - handling HttpChannelState@3ab851e6{s=WOKEN rs=EXPIRE os=OPEN is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:42:02 DEBUG HttpChannelState:391 - nextAction(true) ASYNC_TIMEOUT HttpChannelState@3ab851e6{s=HANDLING rs=EXPIRING os=OPEN is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:42:02 DEBUG HttpChannel:358 - action ASYNC_TIMEOUT HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=HANDLING rs=EXPIRING os=OPEN is=IDLE awp=false se=false i=false al=1},r=1,c=false/false,a=HANDLING,uri=//localhost:8081/subscriptions,age=30318}
2020-02-21 15:42:02 DEBUG HttpChannelState:644 - onTimeout HttpChannelState@3ab851e6{s=HANDLING rs=EXPIRING os=OPEN is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:42:02 DEBUG HttpOutput:739 - write(array HeapByteBuffer@492213d0[p=0,l=15,c=512,r=15]={<<<Gateway timeout>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00})
2020-02-21 15:42:02 DEBUG HttpOutput:797 - write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush DirectByteBuffer@61d804a8[p=0,l=15,c=32768,r=15]={<<<Gateway timeout>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}
2020-02-21 15:42:02 DEBUG HttpChannelState:690 - complete HttpChannelState@3ab851e6{s=HANDLING rs=EXPIRING os=OPEN is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:42:02 DEBUG HttpChannelState:413 - unhandle HttpChannelState@3ab851e6{s=HANDLING rs=COMPLETE os=OPEN is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:42:02 DEBUG HttpChannelState:422 - nextAction(false) COMPLETE HttpChannelState@3ab851e6{s=HANDLING rs=COMPLETING os=OPEN is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:42:02 DEBUG HttpChannel:358 - action COMPLETE HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=HANDLING rs=COMPLETING os=OPEN is=IDLE awp=false se=false i=false al=1},r=1,c=false/false,a=HANDLING,uri=//localhost:8081/subscriptions,age=30332}
2020-02-21 15:42:02 DEBUG HttpOutput:464 - complete(org.eclipse.jetty.util.Callback$4@3dc04670) s=CLOSING,api=BLOCKED,sc=false,e=null s=false e=null, c=DirectByteBuffer@61d804a8[p=0,l=15,c=32768,r=15]={<<<Gateway timeout>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}
2020-02-21 15:42:02 DEBUG HttpChannel:801 - sendResponse info=null content=DirectByteBuffer@61d804a8[p=0,l=15,c=32768,r=15]={<<<Gateway timeout>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00} complete=true committing=true callback=org.eclipse.jetty.server.HttpOutput$WriteCompleteCB@53baafaa
2020-02-21 15:42:02 DEBUG HttpChannel:859 - COMMIT for /subscriptions on HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=HANDLING rs=COMPLETING os=COMMITTED is=IDLE awp=false se=false i=false al=1},r=1,c=false/false,a=HANDLING,uri=//localhost:8081/subscriptions,age=30333}
504 null HTTP/1.1
Content-Type: text/plain;charset=utf-8


2020-02-21 15:42:02 DEBUG HttpConnection:742 - generate: NEED_HEADER for org.eclipse.jetty.server.HttpConnection$SendCallback@5576572b[PROCESSING][i=HTTP/1.1{s=504,h=1,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@2b2b8437] (null,[p=0,l=15,c=32768,r=15],true)@START
2020-02-21 15:42:02 DEBUG HttpGenerator:598 - generateHeaders HTTP/1.1{s=504,h=1,cl=-1} last=true content=DirectByteBuffer@61d804a8[p=0,l=15,c=32768,r=15]={<<<Gateway timeout>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}
2020-02-21 15:42:02 DEBUG HttpGenerator:599 - Content-Type: text/plain;charset=utf-8


2020-02-21 15:42:02 DEBUG HttpGenerator:777 - CONTENT_LENGTH
2020-02-21 15:42:02 DEBUG HttpConnection:742 - generate: FLUSH for org.eclipse.jetty.server.HttpConnection$SendCallback@5576572b[PROCESSING][i=HTTP/1.1{s=504,h=1,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@2b2b8437] ([p=0,l=125,c=8192,r=125],[p=0,l=15,c=32768,r=15],true)@COMPLETING
2020-02-21 15:42:02 DEBUG WriteFlusher:270 - write: WriteFlusher@12c3dc70{IDLE}->null [HeapByteBuffer@49bd562c[p=0,l=125,c=8192,r=125]={<<<HTTP/1.1 504 Gateway Time...y(9.4.26.v20200117)\r\n\r\n>>>f-8021-4d...\x00\x00\x00\x00\x00\x00\x00},DirectByteBuffer@61d804a8[p=0,l=15,c=32768,r=15]={<<<Gateway timeout>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}]
2020-02-21 15:42:02 DEBUG WriteFlusher:112 - update WriteFlusher@12c3dc70{WRITING}->null:IDLE-->WRITING
2020-02-21 15:42:02 DEBUG ChannelEndPoint:279 - flushed 140 SocketChannelEndPoint@3b87331f{/0:0:0:0:0:0:0:1:53423<->/0:0:0:0:0:0:0:1:8081,OPEN,fill=-,flush=W,to=30351/3000000}{io=0/0,kio=0,kro=1}->HttpConnection@15308b22[p=HttpParser{s=CONTENT,0 of 0},g=HttpGenerator@101cd798{s=COMPLETING}]=>HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=HANDLING rs=COMPLETING os=COMMITTED is=IDLE awp=false se=false i=false al=1},r=1,c=false/false,a=HANDLING,uri=//localhost:8081/subscriptions,age=30337}
2020-02-21 15:42:02 DEBUG WriteFlusher:427 - Flushed=true written=140 remaining=0 WriteFlusher@12c3dc70{WRITING}->null
2020-02-21 15:42:02 DEBUG WriteFlusher:112 - update WriteFlusher@12c3dc70{IDLE}->null:WRITING-->IDLE
2020-02-21 15:42:02 DEBUG HttpConnection:742 - generate: DONE for org.eclipse.jetty.server.HttpConnection$SendCallback@5576572b[PROCESSING][i=HTTP/1.1{s=504,h=1,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@2b2b8437] ([p=125,l=125,c=8192,r=0],[p=15,l=15,c=32768,r=0],true)@END
2020-02-21 15:42:02 DEBUG HttpOutput:321 - onWriteComplete(true,null) s=CLOSING,api=BLOCKED,sc=false,e=null->s=CLOSED,api=BLOCKING,sc=false,e=null c=null cb=org.eclipse.jetty.util.Callback$4@3dc04670 w=false
2020-02-21 15:42:02 DEBUG HttpChannelState:952 - completed HttpChannelState@3ab851e6{s=HANDLING rs=COMPLETING os=COMPLETED is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:42:02 DEBUG HttpChannelState:413 - unhandle HttpChannelState@3ab851e6{s=HANDLING rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:42:02 DEBUG HttpChannelState:422 - nextAction(false) TERMINATED HttpChannelState@3ab851e6{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=1}
2020-02-21 15:42:02 DEBUG HttpChannel:358 - action TERMINATED HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=1},r=1,c=true/true,a=IDLE,uri=//localhost:8081/subscriptions,age=30339}
2020-02-21 15:42:02 DEBUG HttpChannel:723 - onCompleted for /subscriptions written=15
2020-02-21 15:42:02 DEBUG HttpConnection:359 - HttpConnection@15308b22::SocketChannelEndPoint@3b87331f{/0:0:0:0:0:0:0:1:53423<->/0:0:0:0:0:0:0:1:8081,OPEN,fill=-,flush=-,to=2/3000000}{io=0/0,kio=0,kro=1}->HttpConnection@15308b22[p=HttpParser{s=CONTENT,0 of 0},g=HttpGenerator@101cd798{s=END}]=>HttpChannelOverHttp@62177c6c{s=HttpChannelState@3ab851e6{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=1},r=1,c=true/true,a=IDLE,uri=//localhost:8081/subscriptions,age=30339} parse null {}




On Fri, Feb 21, 2020 at 3:29 PM Joakim Erdfelt <joakim@xxxxxxxxxxx> wrote:
There's only 1 bit of code in Jetty that will return a 504 Gateway timeout.

The ProxyServlet.

Are you using that?

Joakim Erdfelt / joakim@xxxxxxxxxxx


On Fri, Feb 21, 2020 at 8:09 AM Dániel Sali <daniel.sali@xxxxxxxxxxxxxxxxx> wrote:
Hi all,

I'm writing a REST API in Scala, where an endpoint takes a bit of time to process (>30s), and when I send a POST request to the endpoint, the embedded Jetty server (9.4.26.v20200117) returns an HTTP 504 timeout error.

I've tried increasing the idleTimeout setting for the HTTP connector, but I still get the same error after 30 seconds.

Could you give me pointers on what could be causing this?

Thanks and regards,
Daniel Sali
_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://www.eclipse.org/mailman/listinfo/jetty-users
_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://www.eclipse.org/mailman/listinfo/jetty-users

Back to the top