Issue #736 resolved

REQUEST_METHOD output mangled

Anonymous created an issue

I'm seeing an intermittent issue with CherryPy 3.0.2. The issue is observed via mangled output from cherrypy.log.access() which has request post variables prepended to the http method. For example: - - [01/Oct/2007:21:25:09] "var1=data&var2=data&var3=dataPOST /hook/ HTTP/1.1" 200 - "" """

Snippets from IRC:

{{{ 14:02 < jonojono> im seeing some strange intermittent corruption on incoming requests to a cherryp 14:02 < jonojono> y 3.0.2 server. 14:02 < jonojono> the request line looks like: - - [01/Oct/2007:21:25:09] "var1=data&var2=data&var3=dataPOST /hook/ HTTP/1.1" 200 - "" """ 14:02 < jonojono> any ideas?

14:03 < fumanchu_> what client? 14:47 < jonojono> client is .NET's WebClient.UploadData, also happens to be using 100-continues

14:51 < fumanchu_> jonojono, does cherrypy\test\ work for you? that tests 100-continues 14:54 < jonojono> fumanchu_: yup, test_conn works fine. and requests normally work fine, just a few that experience this weirdness

14:59 < fumanchu_> so is the 100 Continue being sent back OK? does the connection remain open after that 100 response? 15:00 < jonojono> c -> s: POST /blah expect: 100-continue 15:01 < jonojono> s -> c: contentlength: 0 \r\n\r\n 15:01 < jonojono> c -> s: postvars 15:01 < jonojono> s -> c: contentlength:0 \r\n\r\n (an empty response here is expected) 15:02 < fumanchu_> ok, is that first s -> c returning a response code of 100? 15:02 < jonojono> yes 15:06 < jonojono> this issue seems to occur on requests that occur after a request that causes an exception...if that helps add more confusion to the situation :) 15:07 < fumanchu_> no that helps :) 15:09 < fumanchu_> so by "exception" you mean a 500 response? 15:11 < jonojono> affirmative 15:20 < fumanchu_> the previous request that errored, was that a GET or POST? and did it use 100-continue? 15:21 < jonojono> POST, and yes

16:06 < jonojono> fumanchu_: idea... 16:06 < jonojono> so in step 3, when the client sends the server the postvars 16:07 < fumanchu_> uh-huh... 16:10 < jonojono> in wsgiserver/, those postvars may still be hanging in the self.rfile buffer when another request comes in over the persistant connection, then the rfile.readline() on 129 would read in the old post vars appended with the new request line, then the split on 149 would chop off the path/proto, but REQUEST_METHOD would be set to ${postvars}POST", hence the 'corrupted' output im seeing from cherrypy.log.access() 16:18 < fumanchu_> I don't see the circumstances under which postvars would be hanging around 16:19 < jonojono> no clue, but if that did occur, it would match the symptom 16:19 < fumanchu_> the previous request didn't finish reading them? 16:20 < fumanchu_> hmmm 16:21 < fumanchu_> it's possible that the app errored before it finished reading the request body 16:21 < fumanchu_> to tell the server that so it either 1) reads the body data or 2) closes the conn 16:22 < fumanchu_> always close on 500? 16:27 < jonojono> that sounds possible... 16:27 < fumanchu_> would you mind making a ticket with that analysis so far? 16:27 < jonojono> sure }}}

Apologies for the mass-pasting. :-)

Reported by

Comments (5)

  1. Anonymous

    Further evidence to support the above theory of the rfile buffer issue:

    The post variables that are seen prepended to the http method are indeed the post variables of the _previous_ request.

  2. guest

    Some more information that may help debugging: the initial HTTP request from the .NET client does not specify a Connection or Keep-Alive header.

  3. michele

    I'm intermittently experiencing the same problem, I'm using CP 3.0.2 but I've been unable to reproduce it "on demand". It happens whit Firefox + YUI (to post a form using an XHR), I hope to provide more info.

  4. Log in to comment