Ticket #736 (defect)

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:

1.2.3.4 - - [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:  1.2.3.4 - - [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\test_conn.py 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/__init__.py:parse_request(), 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_> so...how 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. :-)