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 <[email protected]> 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 / [email protected]
>
>
> On Fri, Feb 21, 2020 at 8:09 AM Dániel Sali <[email protected]>
> 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
>> [email protected]
>> 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
> [email protected]
> 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
[email protected]
To change your delivery options, retrieve your password, or unsubscribe from
this list, visit
https://www.eclipse.org/mailman/listinfo/jetty-users
