You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@lucene.apache.org by "Chris M. Hostetter (Jira)" <ji...@apache.org> on 2020/09/25 18:37:00 UTC
[jira] [Commented] (SOLR-14896) jetty "Bad Message 400" / "Illegal
character" responses to sporadic requests
[ https://issues.apache.org/jira/browse/SOLR-14896?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17202358#comment-17202358 ]
Chris M. Hostetter commented on SOLR-14896:
-------------------------------------------
Here's an example of this problem occuring with jetty debug logging enabled...
{noformat}
2020-09-25 06:03:21.720 DEBUG (qtp1800649922-203) [ ] o.e.j.h.HttpParser Illegal character VCHAR='/' in state=METHOD for buffer HeapByteBuffer@d24c6d4[p=106,l=1230,c=8192,r=1124]={GET /solr...2 HTTP/<<<1.1\r\nUser-Agent: Solr[org...sion-object-id\x00\x0f\r\n0\r\n\r\n>>>6\x19\x83\x1e\xD9\xC8\x03\x83\xF9...n-5.3.0}
2020-09-25 06:03:21.720 DEBUG (qtp1800649922-203) [ ] o.e.j.h.HttpParser Parse exception: HttpParser{s=METHOD,0 of -1} for HttpChannelOverHttp@16f5abb1{s=HttpChannelState@72cdb650{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=39,c=false/false,a=IDLE,uri=null,age=0} => org.eclipse.jetty.http.HttpParser$IllegalCharacterException: 400: Illegal character VCHAR='/'
at org.eclipse.jetty.http.HttpParser.parseLine(HttpParser.java:654)
org.eclipse.jetty.http.HttpParser$IllegalCharacterException: 400: Illegal character VCHAR='/'
at org.eclipse.jetty.http.HttpParser.parseLine(HttpParser.java:654) ~[jetty-http-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1496) ~[jetty-http-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.server.HttpConnection.parseRequestBuffer(HttpConnection.java:364) ~[jetty-server-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:261) ~[jetty-server-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[jetty-io-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[jetty-io-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) ~[jetty-io-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) ~[jetty-util-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) ~[jetty-util-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[jetty-util-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[jetty-util-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375) ~[jetty-util-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806) ~[jetty-util-9.4.27.v20200227.jar:9.4.27.v20200227]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938) ~[jetty-util-9.4.27.v20200227.jar:9.4.27.v20200227]
at java.lang.Thread.run(Unknown Source) [?:?]
{noformat}
Based on a review of the jetty code, here's my understanding clarification of what exactly the debug message is saying. (NOTE: There seems to be some "off by 1" errors in {{BufferUtil.toDetailString()}} goal of outputing multiples of "8 bytes" at various stages...
* Current state of the HttpParser: attempting to parse the "METHOD" (ie: GET/POST/etc...) on the first line of the request
** {{Illegal character VCHAR='/' in state=METHOD for buffer}}
* Buffer position=106, lenght=1230, capacity=8192, remaining=1124
** {{[p=106,l=1230,c=8192,r=1124]}}
* Initial Characters of the buffer (9 characters at positions 0-8 inclusively): {{GET /solr}}
* The 7 bytes prior to the "current" position: {{2 HTTP/}}
** NOTE: This is the {{/}} that has just been read and caused the error
* the 25 bytes in the buffer starting at the current position: {{1.1\r\nUser-Agent: Solr[org}}
* etc...
The fact that the buffer is at position106 when the parser is still trying to parse the {{METHOD}} seems (to me) to be a pretty clear indication that the buffer it's using is also in use by some other thread which presumably has overwritten the contents of the buffer with it's own content nad "skipped ahead" in it's parsing.
The outstanding question is whether jetty issue#4936 fix in 9.4.30.v20200611 fixes the cause of this problem, or if it represents a _differnet_ buffer polling/sharing bug ?
> jetty "Bad Message 400" / "Illegal character" responses to sporadic requests
> ----------------------------------------------------------------------------
>
> Key: SOLR-14896
> URL: https://issues.apache.org/jira/browse/SOLR-14896
> Project: Solr
> Issue Type: Bug
> Security Level: Public(Default Security Level. Issues are Public)
> Reporter: Chris M. Hostetter
> Priority: Major
>
> I'm getting some offline reports from users who recently upgraded to solr 8.6 of non-reliably reproducing errors from Jetty when doing the HTTP header parsing. these errors result in a jetty response that will typically look something like...
> {noformat}
> HTTP/1.1 400 Illegal character VCHAR='='
> Content-Type: text/html;charset=iso-8859-1
> Content-Length: 70
> Connection: close
> <h1>Bad Message 400</h1><pre>reason: Illegal character VCHAR='='</pre>
> {noformat}
> ...the exact "Illegal character" can vary. Based on some review of the solr/jetty code bases these errors come from Jetty's HttpParser class when unexpected character types are encountered while parsing the HTTP METHOD or Header *NAMES* (VCHAR is a legal token type in Header _VALUES_)
> ----
> These errors sometimes manifest in log files as RemoteSolrExceptions due to intra-node communication, but I've been told they can also be returned directly by solr/jetty when clients make requests -- _even when the client is not using SolrJ_ -- suggesting that whatever is causing the "malformed" request is not specifically a bug in solr/solrj -- this seems like a jetty bug.
> I'm suspect that the underlying cause is jetty buffers being re-used/shared between multiple requests, and suspicious that this is caused by / related to [jetty issue#4936|https://github.com/eclipse/jetty.project/issues/4936] / aka [jetty bug#564984|https://bugs.eclipse.org/bugs/show_bug.cgi?id=564984] .. BUT ... that issue suggests that the buffer re-use situation *ONLY* arises due to a prior "500: Response header too large" error -- but i have not been able to confirm that that situation has ever existed on any of the affected servers where this "400 Illegal character" error occurs.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: issues-unsubscribe@lucene.apache.org
For additional commands, e-mail: issues-help@lucene.apache.org