Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
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 / joakim@xxxxxxxxxxx

On Wed, Aug 12, 2015 at 1:08 PM, X Z <bohr@xxxxxxxx> 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
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users

Back to the top