Re: Assertion in clientProcessBody

On 08/12/2009, at 4:12 PM, Henrik Nordstrom wrote:

> tis 2009-12-08 klockan 13:34 +1100 skrev Mark Nottingham:
>
>> Any thoughts here? Should this really be >=, or should clientProcessBody never get a 0 size_left?
>
> It's done when size_left == 0, and no further body processing handler
> shoud be active on this request at that time. Any data on the connection
> at this time is either surplus data (HTTP violation) or a pipelined
> request waiting to be processed.
>
> If you look a little further down (about one screen) in
> clientProcessBody you'll also see that the body reader gets unregistered
> when processing reaches 0.

is that this?

        /* Remove request link if this is the last part of the body, as
         * clientReadRequest automatically continues to process next request */
        if (conn->body.size_left <= 0 && request != NULL)
            requestUnregisterBody(request, clientReadBody, conn);

I think what's happening here is that conn->body.size_left is 0, but request *is* NULL, because it was a cache hit and clientWriteComplete decided to eat the request body. More verbose logging gave:

2009/12/15 17:09:15| clientReadBody: start fd=35 body_size=226 in.offset=211 cb=0x4562cd req=0xc52f60
2009/12/15 17:09:15| clientProcessBody: start fd=35 body_size=226 in.offset=211 cb=0x4562cd req=0xc52f60
2009/12/15 17:09:15| clientProcessBody: end fd=35 size=211 body_size=15 in.offset=0 cb=0x4562cd req=0xc52f60
2009/12/15 17:09:15| clientReadRequest: FD 35: reading request...
2009/12/15 17:09:15| clientReadRequest: FD 35: read 15 bytes
2009/12/15 17:09:15| clientWriteComplete: FD 35, sz 3705, err 0, off 4200, len 4200
2009/12/15 17:09:15| clientWriteComplete: FD 35 transfer is DONE
2009/12/15 17:09:15| clientWriteComplete: closing, but first we need to read the rest of the request
2009/12/15 17:09:15| clientProcessBody: start fd=35 body_size=15 in.offset=15 cb=0x42ed4c req=(nil)
2009/12/15 17:09:15| clientEatRequestBodyHandler: FD 35 Keeping Alive
2009/12/15 17:09:15| clientKeepaliveNextRequest: FD 35
2009/12/15 17:09:15| httpRequestFree: [url]
2009/12/15 17:09:15| clientKeepaliveNextRequest: FD 35 reading next req
2009/12/15 17:09:15| clientReadRequest: FD 35: reading request...
2009/12/15 17:09:15| clientReadRequest: FD 35: read -1 bytes
2009/12/15 17:09:15| clientProcessBody: end fd=35 size=15 body_size=0 in.offset=0 cb=0x42ed4c req=(nil)
2009/12/15 17:09:15| clientReadBody: start fd=35 body_size=0 in.offset=0 cb=0x4562cd req=0xc52f60
2009/12/15 17:09:15| clientProcessBody: start fd=35 body_size=0 in.offset=0 cb=0x4562cd req=0xc52f60
2009/12/15 17:09:15| clientReadRequest: FD 35: reading request...
2009/12/15 17:09:15| clientReadRequest: FD 35: read 311 bytes
2009/12/15 17:09:15| clientProcessBody: start fd=35 body_size=0 in.offset=311 cb=0x4562cd req=0xc52f60
2009/12/15 17:09:15| assertion failed: client_side.c:4471: "conn->body.size_left > 0"

am I on the right track here?

--
Mark Nottingham       mnot_at_yahoo-inc.com