HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

classic Classic list List threaded Threaded
16 messages Options
X Z
Reply | Threaded
Open this post in threaded view
|

HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

X Z

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

Joakim Erdfelt-8
Can you capture the full POST request line and headers? and post it here?
Would like to see what you are sending.
From the logs, it appears that something with your specific POST request is tripping up the parser.
Best guess, you have a header without a key. (a HTTP spec violation)



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 1:08 PM, X Z <[hidden email]> wrote:

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
X Z
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

X Z

curl -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1


I also tried with "wget http://127.0.0.1:2013/available" which gave me same error code 400.

The above HTTP GET/POST worked with Jetty 9.0 server.

Thanks
zhong



From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 4:53 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Can you capture the full POST request line and headers? and post it here?
Would like to see what you are sending.
From the logs, it appears that something with your specific POST request is tripping up the parser.
Best guess, you have a header without a key. (a HTTP spec violation)



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 1:08 PM, X Z <[hidden email]> wrote:

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

Joakim Erdfelt-8
Just mocked this up based on your descriptions.

A Jetty server using Jetty 9.2.13.v20150730
A servlet on "/mock/*" that has a doGet() and doPost() enabled.
Had the implementation of this servlet just respond what it got.

Using curl to access said servlet.

* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x11588d0
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x11588d0) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> GET /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:07 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 62
* Server Jetty(9.2.13.v20150730) is not blacklisted
< Server: Jetty(9.2.13.v20150730)
GET Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Connection #0 to host 127.0.0.1 left intact
$

$ curl -vv -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1
* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x12da920
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x12da920) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> POST /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 1103791
> Expect: 100-continue
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:53 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 63
< Connection: close
* Server Jetty(9.2.z-SNAPSHOT) is not blacklisted
< Server: Jetty(9.2.z-SNAPSHOT)
POST Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Closing connection 0

Can you use "-vv" on your curl line too?


Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 2:06 PM, X Z <[hidden email]> wrote:

curl -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1


I also tried with "wget http://127.0.0.1:2013/available" which gave me same error code 400.

The above HTTP GET/POST worked with Jetty 9.0 server.

Thanks
zhong



From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 4:53 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Can you capture the full POST request line and headers? and post it here?
Would like to see what you are sending.
From the logs, it appears that something with your specific POST request is tripping up the parser.
Best guess, you have a header without a key. (a HTTP spec violation)



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 1:08 PM, X Z <[hidden email]> wrote:

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
X Z
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

X Z

Here is the details of http post request:


* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> POST /mock/127.0.0.1 HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

> Content-Type: application/json

> Content-Length: 248

* upload completely sent off: 248 out of 248 bytes

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Here is the details of http get request:

* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> GET /available HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Thanks
zhong

From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 5:33 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Just mocked this up based on your descriptions.

A Jetty server using Jetty 9.2.13.v20150730
A servlet on "/mock/*" that has a doGet() and doPost() enabled.
Had the implementation of this servlet just respond what it got.

Using curl to access said servlet.

* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x11588d0
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x11588d0) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> GET /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:07 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 62
* Server Jetty(9.2.13.v20150730) is not blacklisted
< Server: Jetty(9.2.13.v20150730)
GET Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Connection #0 to host 127.0.0.1 left intact
$

$ curl -vv -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1
* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x12da920
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x12da920) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> POST /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 1103791
> Expect: 100-continue
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:53 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 63
< Connection: close
* Server Jetty(9.2.z-SNAPSHOT) is not blacklisted
< Server: Jetty(9.2.z-SNAPSHOT)
POST Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Closing connection 0

Can you use "-vv" on your curl line too?


Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 2:06 PM, X Z <[hidden email]> wrote:

curl -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1


I also tried with "wget http://127.0.0.1:2013/available" which gave me same error code 400.

The above HTTP GET/POST worked with Jetty 9.0 server.

Thanks
zhong



From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 4:53 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Can you capture the full POST request line and headers? and post it here?
Would like to see what you are sending.
From the logs, it appears that something with your specific POST request is tripping up the parser.
Best guess, you have a header without a key. (a HTTP spec violation)



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 1:08 PM, X Z <[hidden email]> wrote:

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

Lothar Kimmeringer
In reply to this post by X Z
Hi,

Am 12.08.2015 um 22:08 schrieb X Z:

> I have upgraded the embedded Jetty server from 9.0 to latest 9.2
> version. The HTTP GET/POST requests return 400 code.

Can you do a System.out.println(server.dump()) after the setup
of the server?


Cheers, Lotahr
_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

Joakim Erdfelt-8
In reply to this post by X Z
I'll see if I can upgrade my curl to your version (I'm older)

Are your requests going through an http proxy perchance?

and/or is your Jetty behind something else? (like apache httpd, haproxy, nginx, etc ...)

Also, if you just run the jetty-distribution's demo-base and hit that with your curl, does it also fail with response code 400?



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 7:52 PM, X Z <[hidden email]> wrote:

Here is the details of http post request:


* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> POST /mock/127.0.0.1 HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

> Content-Type: application/json

> Content-Length: 248

* upload completely sent off: 248 out of 248 bytes

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Here is the details of http get request:

* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> GET /available HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Thanks
zhong

From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 5:33 PM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Just mocked this up based on your descriptions.

A Jetty server using Jetty 9.2.13.v20150730
A servlet on "/mock/*" that has a doGet() and doPost() enabled.
Had the implementation of this servlet just respond what it got.

Using curl to access said servlet.

* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x11588d0
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x11588d0) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> GET /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:07 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 62
* Server Jetty(9.2.13.v20150730) is not blacklisted
< Server: Jetty(9.2.13.v20150730)
GET Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Connection #0 to host 127.0.0.1 left intact
$

$ curl -vv -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1
* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x12da920
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x12da920) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> POST /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 1103791
> Expect: 100-continue
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:53 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 63
< Connection: close
* Server Jetty(9.2.z-SNAPSHOT) is not blacklisted
< Server: Jetty(9.2.z-SNAPSHOT)
POST Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Closing connection 0

Can you use "-vv" on your curl line too?


Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 2:06 PM, X Z <[hidden email]> wrote:

curl -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1


I also tried with "wget http://127.0.0.1:2013/available" which gave me same error code 400.

The above HTTP GET/POST worked with Jetty 9.0 server.

Thanks
zhong



From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 4:53 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Can you capture the full POST request line and headers? and post it here?
Would like to see what you are sending.
From the logs, it appears that something with your specific POST request is tripping up the parser.
Best guess, you have a header without a key. (a HTTP spec violation)



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 1:08 PM, X Z <[hidden email]> wrote:

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
X Z
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

X Z
In reply to this post by Lothar Kimmeringer
org.eclipse.jetty.server.Server@436553c4 - STARTED
 += qtp34907896{STARTED,10<=10<=200,i=5,q=0} - STARTED
 |   +- 30 qtp34907896-30-selector-ServerConnectorManager@67a8a86a/0 RUNNABLE @ sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
 |   +- 31 qtp34907896-31-selector-ServerConnectorManager@67a8a86a/1 RUNNABLE @ sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
 |   +- 32 qtp34907896-32-selector-ServerConnectorManager@67a8a86a/2 RUNNABLE @ sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
 |   +- 33 qtp34907896-33-selector-ServerConnectorManager@67a8a86a/3 RUNNABLE @ sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
 |   +- 34 qtp34907896-34-acceptor-0@149b2743-ServerConnector@51fb87e6{HTTP/1.1}{0.0.0.0:2013} RUNNABLE @ sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
 |   +- 35 qtp34907896-35 WAITING @ sun.misc.Unsafe.park(Native Method)
 |   +- 36 qtp34907896-36 WAITING @ sun.misc.Unsafe.park(Native Method)
 |   +- 37 qtp34907896-37 WAITING @ sun.misc.Unsafe.park(Native Method)
 |   +- 38 qtp34907896-38 WAITING @ sun.misc.Unsafe.park(Native Method)
 |   +- 39 qtp34907896-39 WAITING @ sun.misc.Unsafe.park(Native Method)
 += ServerConnector@51fb87e6{HTTP/1.1}{0.0.0.0:2013} - STARTED
 |   +~ org.eclipse.jetty.server.Server@436553c4 - STARTED
 |   +~ qtp34907896{STARTED,10<=10<=200,i=5,q=0} - STARTED
 |   += org.eclipse.jetty.util.thread.ScheduledExecutorScheduler@989ec37 - STARTED
 |   +- org.eclipse.jetty.io.ArrayByteBufferPool@58973716
 |   += HttpConnectionFactory@32380451{HTTP/1.1} - STARTED
 |   |   +- HttpConfiguration@7ba37b98{32768/8192,8192/8192,https://:0,[]}
 |   += org.eclipse.jetty.server.ServerConnector$ServerConnectorManager@67a8a86a - STARTED
 |   |   +- org.eclipse.jetty.io.SelectorManager$ManagedSelector@5621b307 keys=0 selected=0 id=0
 |   |   |   +- org.eclipse.jetty.io.SelectorManager$ManagedSelector.select(SelectorManager.java:600)
 |   |   |   +- sun.nio.ch.KQueueSelectorImpl@43327a92 keys=0
 |   |   +- org.eclipse.jetty.io.SelectorManager$ManagedSelector@5cdcf6e keys=0 selected=0 id=1
 |   |   |   +- org.eclipse.jetty.io.SelectorManager$ManagedSelector.select(SelectorManager.java:600)
 |   |   |   +- sun.nio.ch.KQueueSelectorImpl@71484698 keys=0
 |   |   +- org.eclipse.jetty.io.SelectorManager$ManagedSelector@3ed76be5 keys=0 selected=0 id=2
 |   |   |   +- org.eclipse.jetty.io.SelectorManager$ManagedSelector.select(SelectorManager.java:600)
 |   |   |   +- sun.nio.ch.KQueueSelectorImpl@61f2ba18 keys=0
 |   |   +- org.eclipse.jetty.io.SelectorManager$ManagedSelector@31470ee1 keys=0 selected=0 id=3
 |   |       +- org.eclipse.jetty.io.SelectorManager$ManagedSelector.select(SelectorManager.java:600)
 |   |       +- sun.nio.ch.KQueueSelectorImpl@6cf27734 keys=0
 |   +- sun.nio.ch.ServerSocketChannelImpl[/0:0:0:0:0:0:0:0:2013]
 |   +- qtp34907896-34-acceptor-0@149b2743-ServerConnector@51fb87e6{HTTP/1.1}{0.0.0.0:2013}
 += o.e.j.s.ServletContextHandler@203af413{/,null,AVAILABLE} - STARTED
 |   += org.eclipse.jetty.server.session.SessionHandler@6f89fe1e - STARTED
 |   |   += org.eclipse.jetty.server.session.HashSessionManager@4c8a9cc7 - STARTED
 |   |   |   += org.eclipse.jetty.util.thread.ScheduledExecutorScheduler@1266dd83 - STARTED
 |   |   |   |   +- sun.misc.Unsafe.park(Native Method)
 |   |   |   |   +- java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
 |   |   |   |   +- java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
 |   |   |   |   +- java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
 |   |   |   |   +- java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
 |   |   |   |   +- java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
 |   |   |   |   +- java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
 |   |   |   |   +- java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
 |   |   |   |   +- java.lang.Thread.run(Thread.java:744)
 |   |   |   +~ org.eclipse.jetty.server.session.HashSessionIdManager@21fea7d8 - STARTED
 |   |   += org.eclipse.jetty.servlet.ServletHandler@3c7c3041 - STARTED
 |   |       += org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher-142a3db5@139de8e==org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher,-1,true - STARTED
 |   |       +- [/*]=>org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher-142a3db5
 |   |       += org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-5546dbd4@2e553f04==org.eclipse.jetty.servlet.ServletHandler$Default404Servlet,-1,false - STARTED
 |   |       +- [/]=>org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-5546dbd4
 |   |
 |   +> No ClassLoader
 |   +> javax.ws.rs.Application=xx.xx.myapplication
 |   +> org.eclipse.jetty.server.Executor=qtp34907896{STARTED,10<=10<=200,i=5,q=0}
 |   +> org.jboss.resteasy.core.Dispatcher=org.jboss.resteasy.core.SynchronousDispatcher@7310a664
 |   +> org.jboss.resteasy.spi.Registry=org.jboss.resteasy.core.ResourceMethodRegistry@4a1c2a40
 |   +> resteasy.deployments={=org.jboss.resteasy.spi.ResteasyDeployment@7f19f5c2}
 |   +> org.jboss.resteasy.spi.ResteasyProviderFactory=org.jboss.resteasy.spi.ResteasyProviderFactory@155d4bf
 += org.eclipse.jetty.server.session.HashSessionIdManager@21fea7d8 - STARTED
 |

________________________________________
From: [hidden email] <[hidden email]> on behalf of Lothar Kimmeringer <[hidden email]>
Sent: Thursday, August 13, 2015 5:39 AM
To: [hidden email]
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

Hi,

Am 12.08.2015 um 22:08 schrieb X Z:

> I have upgraded the embedded Jetty server from 9.0 to latest 9.2
> version. The HTTP GET/POST requests return 400 code.

Can you do a System.out.println(server.dump()) after the setup
of the server?


Cheers, Lotahr
_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
X Z
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

X Z
In reply to this post by Joakim Erdfelt-8

I am using embedded jetty, and there is no http proxy. My embedded jetty server works with RestEasy (3.0.9.Finalto provide restful. 


Thanks
Xuan


From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Thursday, August 13, 2015 9:02 AM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
I'll see if I can upgrade my curl to your version (I'm older)

Are your requests going through an http proxy perchance?

and/or is your Jetty behind something else? (like apache httpd, haproxy, nginx, etc ...)

Also, if you just run the jetty-distribution's demo-base and hit that with your curl, does it also fail with response code 400?



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 7:52 PM, X Z <[hidden email]> wrote:

Here is the details of http post request:


* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> POST /mock/127.0.0.1 HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

> Content-Type: application/json

> Content-Length: 248

* upload completely sent off: 248 out of 248 bytes

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Here is the details of http get request:

* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> GET /available HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Thanks
zhong

From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 5:33 PM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Just mocked this up based on your descriptions.

A Jetty server using Jetty 9.2.13.v20150730
A servlet on "/mock/*" that has a doGet() and doPost() enabled.
Had the implementation of this servlet just respond what it got.

Using curl to access said servlet.

* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x11588d0
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x11588d0) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> GET /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:07 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 62
* Server Jetty(9.2.13.v20150730) is not blacklisted
< Server: Jetty(9.2.13.v20150730)
* Connection #0 to host 127.0.0.1 left intact
$

$ curl -vv -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1
* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x12da920
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x12da920) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> POST /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 1103791
> Expect: 100-continue
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:53 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 63
< Connection: close
* Server Jetty(9.2.z-SNAPSHOT) is not blacklisted
< Server: Jetty(9.2.z-SNAPSHOT)
POST Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Closing connection 0

Can you use "-vv" on your curl line too?


Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 2:06 PM, X Z <[hidden email]> wrote:

curl -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1


I also tried with "wget http://127.0.0.1:2013/available" which gave me same error code 400.

The above HTTP GET/POST worked with Jetty 9.0 server.

Thanks
zhong



From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 4:53 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Can you capture the full POST request line and headers? and post it here?
Would like to see what you are sending.
From the logs, it appears that something with your specific POST request is tripping up the parser.
Best guess, you have a header without a key. (a HTTP spec violation)



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 1:08 PM, X Z <[hidden email]> wrote:

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

Joakim Erdfelt-8
Hmm.
I wonder if the 400 you are seeing is from RestEasy attempting to do a request.getRequestDispatcher(String path) call improperly.
If you disable RestEasy (temporarily), does the 400 go away?

Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 8:47 AM, X Z <[hidden email]> wrote:

I am using embedded jetty, and there is no http proxy. My embedded jetty server works with RestEasy (3.0.9.Finalto provide restful. 


Thanks
Xuan


From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Thursday, August 13, 2015 9:02 AM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
I'll see if I can upgrade my curl to your version (I'm older)

Are your requests going through an http proxy perchance?

and/or is your Jetty behind something else? (like apache httpd, haproxy, nginx, etc ...)

Also, if you just run the jetty-distribution's demo-base and hit that with your curl, does it also fail with response code 400?



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 7:52 PM, X Z <[hidden email]> wrote:

Here is the details of http post request:


* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> POST /mock/127.0.0.1 HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

> Content-Type: application/json

> Content-Length: 248

* upload completely sent off: 248 out of 248 bytes

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Here is the details of http get request:

* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> GET /available HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Thanks
zhong

From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 5:33 PM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Just mocked this up based on your descriptions.

A Jetty server using Jetty 9.2.13.v20150730
A servlet on "/mock/*" that has a doGet() and doPost() enabled.
Had the implementation of this servlet just respond what it got.

Using curl to access said servlet.

* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x11588d0
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x11588d0) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> GET /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:07 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 62
* Server Jetty(9.2.13.v20150730) is not blacklisted
< Server: Jetty(9.2.13.v20150730)
* Connection #0 to host 127.0.0.1 left intact
$

$ curl -vv -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1
* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x12da920
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x12da920) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> POST /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 1103791
> Expect: 100-continue
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:53 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 63
< Connection: close
* Server Jetty(9.2.z-SNAPSHOT) is not blacklisted
< Server: Jetty(9.2.z-SNAPSHOT)
POST Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Closing connection 0

Can you use "-vv" on your curl line too?


Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 2:06 PM, X Z <[hidden email]> wrote:

curl -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1


I also tried with "wget http://127.0.0.1:2013/available" which gave me same error code 400.

The above HTTP GET/POST worked with Jetty 9.0 server.

Thanks
zhong



From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 4:53 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Can you capture the full POST request line and headers? and post it here?
Would like to see what you are sending.
From the logs, it appears that something with your specific POST request is tripping up the parser.
Best guess, you have a header without a key. (a HTTP spec violation)



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 1:08 PM, X Z <[hidden email]> wrote:

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

Joakim Erdfelt-8
Also, what are the jars/classes you have in your project?
I'm wondering if there is a fundamental conflict somewhere (like a mismatch in org.eclipse.jetty.http classes for example)

Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 9:33 AM, Joakim Erdfelt <[hidden email]> wrote:
Hmm.
I wonder if the 400 you are seeing is from RestEasy attempting to do a request.getRequestDispatcher(String path) call improperly.
If you disable RestEasy (temporarily), does the 400 go away?

Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 8:47 AM, X Z <[hidden email]> wrote:

I am using embedded jetty, and there is no http proxy. My embedded jetty server works with RestEasy (3.0.9.Finalto provide restful. 


Thanks
Xuan


From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Thursday, August 13, 2015 9:02 AM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
I'll see if I can upgrade my curl to your version (I'm older)

Are your requests going through an http proxy perchance?

and/or is your Jetty behind something else? (like apache httpd, haproxy, nginx, etc ...)

Also, if you just run the jetty-distribution's demo-base and hit that with your curl, does it also fail with response code 400?



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 7:52 PM, X Z <[hidden email]> wrote:

Here is the details of http post request:


* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> POST /mock/127.0.0.1 HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

> Content-Type: application/json

> Content-Length: 248

* upload completely sent off: 248 out of 248 bytes

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Here is the details of http get request:

* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> GET /available HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Thanks
zhong

From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 5:33 PM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Just mocked this up based on your descriptions.

A Jetty server using Jetty 9.2.13.v20150730
A servlet on "/mock/*" that has a doGet() and doPost() enabled.
Had the implementation of this servlet just respond what it got.

Using curl to access said servlet.

* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x11588d0
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x11588d0) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> GET /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:07 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 62
* Server Jetty(9.2.13.v20150730) is not blacklisted
< Server: Jetty(9.2.13.v20150730)
* Connection #0 to host 127.0.0.1 left intact
$

$ curl -vv -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1
* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x12da920
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x12da920) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> POST /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 1103791
> Expect: 100-continue
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:53 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 63
< Connection: close
* Server Jetty(9.2.z-SNAPSHOT) is not blacklisted
< Server: Jetty(9.2.z-SNAPSHOT)
POST Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Closing connection 0

Can you use "-vv" on your curl line too?


Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 2:06 PM, X Z <[hidden email]> wrote:

curl -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1


I also tried with "wget http://127.0.0.1:2013/available" which gave me same error code 400.

The above HTTP GET/POST worked with Jetty 9.0 server.

Thanks
zhong



From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 4:53 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Can you capture the full POST request line and headers? and post it here?
Would like to see what you are sending.
From the logs, it appears that something with your specific POST request is tripping up the parser.
Best guess, you have a header without a key. (a HTTP spec violation)



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 1:08 PM, X Z <[hidden email]> wrote:

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users



_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
X Z
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

X Z

I did try to disable RestEasy, and use the jetty servlet to create an example servlet, still same error code. I didn't notice any mismatch in the dependency jars. But this error code only happened when I use Jetty 9.2, and Jetty 9.0 just worked fine. Another interesting finding is that two wget clients had different results:

wget --version

GNU Wget 1.11.4 Red Hat modified


wget http://remotehost:2013/example

--2015-08-13 16:02:30--  http://remotehost:2013/example

Connecting to remotehost:2013... connected.

HTTP request sent, awaiting response... 302 Found

Location: http://remotehost:2013/example/ [following]

--2015-08-13 16:02:30--  http://remotehost:2013/example/

Reusing existing connection to remotehost:2013.

HTTP request sent, awaiting response... 200 OK

Length: 14

Saving to: `index.html'


wget --version

GNU Wget 1.16.3 built on darwin14.3.0.

wget http://127.0.0.1:2013/example

--2015-08-13 17:11:15--  http://127.0.0.1:2013/example

Connecting to 127.0.0.1:2013... connected.

HTTP request sent, awaiting response... 400 Bad Request

2015-08-13 17:11:16 ERROR 400: Bad Request.


Any clues?


Thanks

zhong




From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Thursday, August 13, 2015 12:40 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Also, what are the jars/classes you have in your project?
I'm wondering if there is a fundamental conflict somewhere (like a mismatch in org.eclipse.jetty.http classes for example)

Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 9:33 AM, Joakim Erdfelt <[hidden email]> wrote:
Hmm.
I wonder if the 400 you are seeing is from RestEasy attempting to do a request.getRequestDispatcher(String path) call improperly.
If you disable RestEasy (temporarily), does the 400 go away?

Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 8:47 AM, X Z <[hidden email]> wrote:

I am using embedded jetty, and there is no http proxy. My embedded jetty server works with RestEasy (3.0.9.Finalto provide restful. 


Thanks
Xuan


From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Thursday, August 13, 2015 9:02 AM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
I'll see if I can upgrade my curl to your version (I'm older)

Are your requests going through an http proxy perchance?

and/or is your Jetty behind something else? (like apache httpd, haproxy, nginx, etc ...)

Also, if you just run the jetty-distribution's demo-base and hit that with your curl, does it also fail with response code 400?



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 7:52 PM, X Z <[hidden email]> wrote:

Here is the details of http post request:


* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> POST /mock/127.0.0.1 HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

> Content-Type: application/json

> Content-Length: 248

* upload completely sent off: 248 out of 248 bytes

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Here is the details of http get request:

* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> GET /available HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Thanks
zhong

From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 5:33 PM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Just mocked this up based on your descriptions.

A Jetty server using Jetty 9.2.13.v20150730
A servlet on "/mock/*" that has a doGet() and doPost() enabled.
Had the implementation of this servlet just respond what it got.

Using curl to access said servlet.

* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x11588d0
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x11588d0) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> GET /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:07 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 62
* Server Jetty(9.2.13.v20150730) is not blacklisted
< Server: Jetty(9.2.13.v20150730)
* Connection #0 to host 127.0.0.1 left intact
$

$ curl -vv -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1
* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x12da920
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x12da920) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> POST /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 1103791
> Expect: 100-continue
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:53 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 63
< Connection: close
* Server Jetty(9.2.z-SNAPSHOT) is not blacklisted
< Server: Jetty(9.2.z-SNAPSHOT)
POST Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Closing connection 0

Can you use "-vv" on your curl line too?


Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 2:06 PM, X Z <[hidden email]> wrote:

curl -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1


I also tried with "wget http://127.0.0.1:2013/available" which gave me same error code 400.

The above HTTP GET/POST worked with Jetty 9.0 server.

Thanks
zhong



From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 4:53 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Can you capture the full POST request line and headers? and post it here?
Would like to see what you are sending.
From the logs, it appears that something with your specific POST request is tripping up the parser.
Best guess, you have a header without a key. (a HTTP spec violation)



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 1:08 PM, X Z <[hidden email]> wrote:

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users



_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

Joakim Erdfelt-8
There's something really fundamental going on.
A firewall, a proxy, some malware, a bad set of jars/classes, bad hardware, etc ...
This is simply not reproducible.

I went ahead and put the test server i'm using on github.

It doesn't fail if I run the server on OSX (10.9 or 10.10), Linux (ubuntu 12.04, fedora 20, or debian wheezy), or Windows (windows 7, windows 8, or windows 10).
It doesn't matter if i use OpenJDK 7u72, Oracle JDK 7u75, 8u45, or 8u51.
It doesn't matter if I test locally, or remotely. 
It doesn't fail with curl, wget, java.net.URLConnection, chrome, firefox, or even using netcat.

Can you please run this test server and see if you can replicate using curl or wget?
If you can replicate, the output from that server will include your relevant System properties. (maybe that will help)


Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 2:18 PM, X Z <[hidden email]> wrote:

I did try to disable RestEasy, and use the jetty servlet to create an example servlet, still same error code. I didn't notice any mismatch in the dependency jars. But this error code only happened when I use Jetty 9.2, and Jetty 9.0 just worked fine. Another interesting finding is that two wget clients had different results:

wget --version

GNU Wget 1.11.4 Red Hat modified


wget http://remotehost:2013/example

--2015-08-13 16:02:30--  http://remotehost:2013/example

Connecting to remotehost:2013... connected.

HTTP request sent, awaiting response... 302 Found

Location: http://remotehost:2013/example/ [following]

--2015-08-13 16:02:30--  http://remotehost:2013/example/

Reusing existing connection to remotehost:2013.

HTTP request sent, awaiting response... 200 OK

Length: 14

Saving to: `index.html'


wget --version

GNU Wget 1.16.3 built on darwin14.3.0.

wget http://127.0.0.1:2013/example

--2015-08-13 17:11:15--  http://127.0.0.1:2013/example

Connecting to 127.0.0.1:2013... connected.

HTTP request sent, awaiting response... 400 Bad Request

2015-08-13 17:11:16 ERROR 400: Bad Request.


Any clues?


Thanks

zhong




From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Thursday, August 13, 2015 12:40 PM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Also, what are the jars/classes you have in your project?
I'm wondering if there is a fundamental conflict somewhere (like a mismatch in org.eclipse.jetty.http classes for example)

Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 9:33 AM, Joakim Erdfelt <[hidden email]> wrote:
Hmm.
I wonder if the 400 you are seeing is from RestEasy attempting to do a request.getRequestDispatcher(String path) call improperly.
If you disable RestEasy (temporarily), does the 400 go away?

Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 8:47 AM, X Z <[hidden email]> wrote:

I am using embedded jetty, and there is no http proxy. My embedded jetty server works with RestEasy (3.0.9.Finalto provide restful. 


Thanks
Xuan


From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Thursday, August 13, 2015 9:02 AM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
I'll see if I can upgrade my curl to your version (I'm older)

Are your requests going through an http proxy perchance?

and/or is your Jetty behind something else? (like apache httpd, haproxy, nginx, etc ...)

Also, if you just run the jetty-distribution's demo-base and hit that with your curl, does it also fail with response code 400?



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 7:52 PM, X Z <[hidden email]> wrote:

Here is the details of http post request:


* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> POST /mock/127.0.0.1 HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

> Content-Type: application/json

> Content-Length: 248

* upload completely sent off: 248 out of 248 bytes

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Here is the details of http get request:

* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> GET /available HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Thanks
zhong

From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 5:33 PM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Just mocked this up based on your descriptions.

A Jetty server using Jetty 9.2.13.v20150730
A servlet on "/mock/*" that has a doGet() and doPost() enabled.
Had the implementation of this servlet just respond what it got.

Using curl to access said servlet.

* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x11588d0
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x11588d0) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> GET /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:07 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 62
* Server Jetty(9.2.13.v20150730) is not blacklisted
< Server: Jetty(9.2.13.v20150730)
* Connection #0 to host 127.0.0.1 left intact
$

$ curl -vv -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1
* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x12da920
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x12da920) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> POST /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 1103791
> Expect: 100-continue
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:53 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 63
< Connection: close
* Server Jetty(9.2.z-SNAPSHOT) is not blacklisted
< Server: Jetty(9.2.z-SNAPSHOT)
POST Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Closing connection 0

Can you use "-vv" on your curl line too?


Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 2:06 PM, X Z <[hidden email]> wrote:

curl -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1


I also tried with "wget http://127.0.0.1:2013/available" which gave me same error code 400.

The above HTTP GET/POST worked with Jetty 9.0 server.

Thanks
zhong



From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 4:53 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Can you capture the full POST request line and headers? and post it here?
Would like to see what you are sending.
From the logs, it appears that something with your specific POST request is tripping up the parser.
Best guess, you have a header without a key. (a HTTP spec violation)



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 1:08 PM, X Z <[hidden email]> wrote:

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users



_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

Joakim Erdfelt-8
Tested again with the same wget you have ...

$ wget --debug http://localhost:2013/mock/127.0.0.1
DEBUG output created by Wget 1.16.3 on darwin14.1.0.

URI encoding = ‘UTF-8’
--2015-08-13 15:14:54--  http://localhost:2013/mock/127.0.0.1
Resolving localhost (localhost)... ::1, 127.0.0.1
Caching localhost => ::1 127.0.0.1
Connecting to localhost (localhost)|::1|:2013... connected.
Created socket 6.
Releasing 0x00007fb2d0700040 (new refcount 1).

---request begin---
GET /mock/127.0.0.1 HTTP/1.1
User-Agent: Wget/1.16.3 (darwin14.1.0)
Accept: */*
Accept-Encoding: identity
Host: localhost:2013
Connection: Keep-Alive

---request end---
HTTP request sent, awaiting response...
---response begin---
HTTP/1.1 200 OK
Date: Thu, 13 Aug 2015 22:14:54 GMT
Content-Type: text/plain; charset=ISO-8859-1
Content-Length: 62
Server: Jetty(9.2.13.v20150730)

---response end---
200 OK
Registered socket 6 for persistent reuse.
URI content encoding = ‘ISO-8859-1’
Length: 62 [text/plain]
Saving to: ‘127.0.0.1.2’

127.0.0.1.2         100%[=====================>]      62  --.-KB/s   in 0s

2015-08-13 15:14:54 (8.45 MB/s) - ‘127.0.0.1.2’ saved [62/62]



Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 3:08 PM, Joakim Erdfelt <[hidden email]> wrote:
There's something really fundamental going on.
A firewall, a proxy, some malware, a bad set of jars/classes, bad hardware, etc ...
This is simply not reproducible.

I went ahead and put the test server i'm using on github.

It doesn't fail if I run the server on OSX (10.9 or 10.10), Linux (ubuntu 12.04, fedora 20, or debian wheezy), or Windows (windows 7, windows 8, or windows 10).
It doesn't matter if i use OpenJDK 7u72, Oracle JDK 7u75, 8u45, or 8u51.
It doesn't matter if I test locally, or remotely. 
It doesn't fail with curl, wget, java.net.URLConnection, chrome, firefox, or even using netcat.

Can you please run this test server and see if you can replicate using curl or wget?
If you can replicate, the output from that server will include your relevant System properties. (maybe that will help)


Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 2:18 PM, X Z <[hidden email]> wrote:

I did try to disable RestEasy, and use the jetty servlet to create an example servlet, still same error code. I didn't notice any mismatch in the dependency jars. But this error code only happened when I use Jetty 9.2, and Jetty 9.0 just worked fine. Another interesting finding is that two wget clients had different results:

wget --version

GNU Wget 1.11.4 Red Hat modified


wget http://remotehost:2013/example

--2015-08-13 16:02:30--  http://remotehost:2013/example

Connecting to remotehost:2013... connected.

HTTP request sent, awaiting response... 302 Found

Location: http://remotehost:2013/example/ [following]

--2015-08-13 16:02:30--  http://remotehost:2013/example/

Reusing existing connection to remotehost:2013.

HTTP request sent, awaiting response... 200 OK

Length: 14

Saving to: `index.html'


wget --version

GNU Wget 1.16.3 built on darwin14.3.0.

wget http://127.0.0.1:2013/example

--2015-08-13 17:11:15--  http://127.0.0.1:2013/example

Connecting to 127.0.0.1:2013... connected.

HTTP request sent, awaiting response... 400 Bad Request

2015-08-13 17:11:16 ERROR 400: Bad Request.


Any clues?


Thanks

zhong




From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Thursday, August 13, 2015 12:40 PM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Also, what are the jars/classes you have in your project?
I'm wondering if there is a fundamental conflict somewhere (like a mismatch in org.eclipse.jetty.http classes for example)

Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 9:33 AM, Joakim Erdfelt <[hidden email]> wrote:
Hmm.
I wonder if the 400 you are seeing is from RestEasy attempting to do a request.getRequestDispatcher(String path) call improperly.
If you disable RestEasy (temporarily), does the 400 go away?

Joakim Erdfelt / [hidden email]

On Thu, Aug 13, 2015 at 8:47 AM, X Z <[hidden email]> wrote:

I am using embedded jetty, and there is no http proxy. My embedded jetty server works with RestEasy (3.0.9.Finalto provide restful. 


Thanks
Xuan


From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Thursday, August 13, 2015 9:02 AM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
I'll see if I can upgrade my curl to your version (I'm older)

Are your requests going through an http proxy perchance?

and/or is your Jetty behind something else? (like apache httpd, haproxy, nginx, etc ...)

Also, if you just run the jetty-distribution's demo-base and hit that with your curl, does it also fail with response code 400?



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 7:52 PM, X Z <[hidden email]> wrote:

Here is the details of http post request:


* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> POST /mock/127.0.0.1 HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

> Content-Type: application/json

> Content-Length: 248

* upload completely sent off: 248 out of 248 bytes

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Here is the details of http get request:

* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...

* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)

> GET /available HTTP/1.1

> User-Agent: curl/7.37.1

> Host: 127.0.0.1:2013

> Accept: */*

< HTTP/1.1 400 Bad Request

< Content-Length: 0

< Connection: close

* Server Jetty(9.2.13.v20150730) is not blacklisted

< Server: Jetty(9.2.13.v20150730)

* Closing connection 0



Thanks
zhong

From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 5:33 PM

To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Just mocked this up based on your descriptions.

A Jetty server using Jetty 9.2.13.v20150730
A servlet on "/mock/*" that has a doGet() and doPost() enabled.
Had the implementation of this servlet just respond what it got.

Using curl to access said servlet.

* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x11588d0
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x11588d0) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> GET /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:07 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 62
* Server Jetty(9.2.13.v20150730) is not blacklisted
< Server: Jetty(9.2.13.v20150730)
* Connection #0 to host 127.0.0.1 left intact
$

$ curl -vv -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1
* About to connect() to 127.0.0.1 port 2013 (#0)
*   Trying 127.0.0.1...
* Adding handle: conn: 0x12da920
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x12da920) send_pipe: 1, recv_pipe: 0
* Connected to 127.0.0.1 (127.0.0.1) port 2013 (#0)
> POST /mock/127.0.0.1 HTTP/1.1
> User-Agent: curl/7.32.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 1103791
> Expect: 100-continue
< HTTP/1.1 200 OK
< Date: Wed, 12 Aug 2015 21:32:53 GMT
< Content-Type: text/plain; charset=ISO-8859-1
< Content-Length: 63
< Connection: close
* Server Jetty(9.2.z-SNAPSHOT) is not blacklisted
< Server: Jetty(9.2.z-SNAPSHOT)
POST Request received for http://127.0.0.1:2013/mock/127.0.0.1
* Closing connection 0

Can you use "-vv" on your curl line too?


Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 2:06 PM, X Z <[hidden email]> wrote:

curl -H "Content-Type: application/json" --data @si.json http://127.0.0.1:2013/mock/127.0.0.1


I also tried with "wget http://127.0.0.1:2013/available" which gave me same error code 400.

The above HTTP GET/POST worked with Jetty 9.0 server.

Thanks
zhong



From: [hidden email] <[hidden email]> on behalf of Joakim Erdfelt <[hidden email]>
Sent: Wednesday, August 12, 2015 4:53 PM
To: JETTY user mailing list
Subject: Re: [jetty-users] HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2
 
Can you capture the full POST request line and headers? and post it here?
Would like to see what you are sending.
From the logs, it appears that something with your specific POST request is tripping up the parser.
Best guess, you have a header without a key. (a HTTP spec violation)



Joakim Erdfelt / [hidden email]

On Wed, Aug 12, 2015 at 1:08 PM, X Z <[hidden email]> wrote:

Hi,


I have upgraded the embedded Jetty server from 9.0 to latest 9.2 version. The HTTP GET/POST requests return 400 code. I also saw this warning log:

WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

Anyone has got the insight on how to fix the issue? 


The detailed debugging messages are:

015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 0/0 selected

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Accept@55c4b148

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onOpen SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG IdleTimeout:89 - SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0} idle timeout check, elapsed: 3 ms, remaining: 29997 ms

2015-08-12 15:51:55 DEBUG HttpChannel:89 - new HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-} -> SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,29/30000,null}{io=0,kio=0,kro=0},null,HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG HttpConnection:89 - New HTTP Connection HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onOpen HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - fillInterested HttpConnection@45d14aaa{IDLE}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - IDLE-->FILL_INTERESTED HttpConnection@45d14aaa{FILL_INTERESTED}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 0 -> 1 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,0/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Created SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,1/30000,HttpConnection}{io=1,kio=0,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 0 -> 1 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=1,kro=0}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop woken up from select, 1/1 selected

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Key interests updated 1 -> 0 on SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,2/30000,HttpConnection}{io=1,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectChannelEndPoint:89 - Local interests updating 1 -> 0 for SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,R,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILL_INTERESTED-->FILLING HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@320dce4f

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Selector loop waiting on select

2015-08-12 15:51:55 DEBUG HttpConnection:89 - HttpConnection@45d14aaa{FILLING} onFillable HttpChannelState@78442dc2{s=IDLE i=true a=null}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled 394 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,4/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=START HeapByteBuffer@2c5c9e4a[p=0,l=394,c=8192,r=394]={<<<POST /mock/127.0....d":"127.0.0.1"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG HttpParser:89 - START --> SPACE1

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE1 --> URI

2015-08-12 15:51:55 DEBUG HttpParser:89 - URI --> SPACE2

2015-08-12 15:51:55 DEBUG HttpParser:89 - SPACE2 --> REQUEST_VERSION

2015-08-12 15:51:55 DEBUG HttpParser:89 - REQUEST_VERSION --> HEADER

2015-08-12 15:51:55 WARN  HttpParser:59 - badMessage: java.lang.ArrayIndexOutOfBoundsException: 0 for HttpChannelOverHttp@2e70eea7{r=0,c=false,a=IDLE,uri=-}

2015-08-12 15:51:55 DEBUG HttpParser:105 - 

java.lang.ArrayIndexOutOfBoundsException: 0

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:374)

at org.eclipse.jetty.util.ArrayTernaryTrie.getBest(ArrayTernaryTrie.java:357)

at org.eclipse.jetty.http.HttpParser.parseHeaders(HttpParser.java:1047)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1257)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:250)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:744)

2015-08-12 15:51:55 DEBUG HttpParser:89 - HEADER --> CLOSED

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=IDLE i=true a=null} handling IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: NEED_HEADER (null,null,true)@START

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: FLUSH ([p=0,l=99,c=8192,r=99],null,true)@COMPLETING

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - write: WriteFlusher@5bd3465a{IDLE} [HeapByteBuffer@4e26e633[p=0,l=99,c=8192,r=99]={<<<HTTP/1.1 400 Bad ....v20150730)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{WRITING}:IDLE-->WRITING

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - flushed 99 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,W,10/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG WriteFlusher:89 - update WriteFlusher@5bd3465a{IDLE}:WRITING-->IDLE

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: SHUTDOWN_OUT ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG HttpConnection:89 - org.eclipse.jetty.server.HttpConnection$SendCallback@4652a2dd[PROCESSING][i=ResponseInfo{HTTP/1.1 400 null,0,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5b427f3c] generate: DONE ([p=99,l=99,c=8192,r=0],null,true)@END

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - oshut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,out,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG HttpChannelState:89 - HttpChannelState@78442dc2{s=DISPATCHED i=true a=null} unhandle DISPATCHED

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - filled -1 SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,1/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - ishut SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,Open,in,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,2/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG ChannelEndPoint:89 - close SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=0,kro=1}

2015-08-12 15:51:55 DEBUG SelectorManager:89 - Destroyed SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,3/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - onClose HttpConnection@45d14aaa{FILLING}

2015-08-12 15:51:55 DEBUG AbstractEndPoint:89 - onClose SelectChannelEndPoint@57f83f44{/127.0.0.1:60062<->2013,CLOSED,ISHUT,OSHUT,-,-,4/30000,HttpConnection}{io=0,kio=-1,kro=-1}

2015-08-12 15:51:55 DEBUG HttpParser:89 - atEOF HttpParser{s=CLOSED,0 of 0}

2015-08-12 15:51:55 DEBUG HttpParser:89 - parseNext s=CLOSED HeapByteBuffer@4e26e633[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

2015-08-12 15:51:55 DEBUG AbstractConnection:89 - FILLING-->IDLE HttpConnection@45d14aaa{IDLE}


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users



_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users



_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

Lothar Kimmeringer
In reply to this post by X Z
Hi,

Am 13.08.2015 um 23:18 schrieb X Z:
> wget --version
> GNU Wget 1.11.4 Red Hat modified
[...]
> HTTP request sent, awaiting response... 200 OK
[...]
> wget --version
> GNU Wget 1.16.3 built on darwin14.3.0.
[...]
> 2015-08-13 17:11:16 ERROR 400: Bad Request.

Can you do a TCP-dump on the server-side with these two requests
and compare the two HTTP-request on byte-level?

The server dump doesn't look wrong IME.


Cheers, Lothar
_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users
Reply | Threaded
Open this post in threaded view
|

Re: HTTP 400 status code returned after Jetty server upgraded from 9.0 to 9.2

Joakim Erdfelt-8
I agree with Lothar, at this point we need to see a tcpdump (the raw, on-network, as-sent) bytes to get an inkling on what's going on.

I trust curl and wget to do the right thing.
However, while they could be doing the right thing, something else is modifying that right thing before it gets to the server.
Such a modification should be obvious when analyzing a tcpdump.



Joakim Erdfelt / [hidden email]

On Fri, Aug 14, 2015 at 6:36 AM, Lothar Kimmeringer <[hidden email]> wrote:
Hi,

Am 13.08.2015 um 23:18 schrieb X Z:
> wget --version
> GNU Wget 1.11.4 Red Hat modified
[...]
> HTTP request sent, awaiting response... 200 OK
[...]
> wget --version
> GNU Wget 1.16.3 built on darwin14.3.0.
[...]
> 2015-08-13 17:11:16 ERROR 400: Bad Request.

Can you do a TCP-dump on the server-side with these two requests
and compare the two HTTP-request on byte-level?

The server dump doesn't look wrong IME.


Cheers, Lothar
_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
[hidden email]
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users