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 m...@yahoo-inc.com
Re: Assertion in clientProcessBody
debug_options 33,2 results in: 2009/12/08 18:34:24| clientTryParseRequest: 0xdbeac0: FD 54: request body is 226 bytes in size 2009/12/08 18:34:24| The request GET [URL] is ALLOWED, because it matched '[acl]' 2009/12/08 18:34:24| clientCacheHit: refreshCheckHTTPStale returned -2 2009/12/08 18:34:24| clientCacheHit: stale-while-revalidate needs revalidation 2009/12/08 18:34:24| The reply for GET [URL] is ALLOWED, because it matched 'all' 2009/12/08 18:34:24| clientProcessBody: start fd=54 body_size=226 in.offset=226 cb=0x42eac0 req=(nil) 2009/12/08 18:34:24| clientProcessBody: end fd=54 size=226 body_size=0 in.offset=0 cb=0x42eac0 req=(nil) 2009/12/08 18:34:24| clientReadBody: start fd=54 body_size=0 in.offset=0 cb=0x45602f req=0xdbeac0 2009/12/08 18:34:24| clientProcessBody: start fd=54 body_size=0 in.offset=0 cb=0x45602f req=0xdbeac0 2009/12/08 18:34:24| The request GET [URL2] is ALLOWED, because it matched '[acl]' 2009/12/08 18:34:24| clientCacheHit: refreshCheckHTTPStale returned -2 2009/12/08 18:34:24| clientCacheHit: stale-while-revalidate needs revalidation 2009/12/08 18:34:24| The reply for GET [URL2] is ALLOWED, because it matched 'all' 2009/12/08 18:34:24| clientProcessBody: start fd=54 body_size=0 in.offset=420 cb=0x45602f req=0xdbeac0 2009/12/08 18:34:24| assertion failed: client_side.c:4445: conn-body.size_left 0 On 08/12/2009, at 5:23 PM, Mark Nottingham wrote: #2 0x00435749 in xassert (msg=0x4c02f1 conn-body.size_left 0, file=0x4bd9d0 client_side.c, line=4445) at debug.c:505 No locals. #3 0x0042ece1 in clientProcessBody (conn=0xc270c8) at client_side.c:4445 valid = 1 size = 0 buf = 0x81024f0 cbdata = (void *) 0x51703568 callback = (CBCB *) 0x45602f httpRequestBodyHandler request = (request_t *) 0x1ed3c80 #4 0x0042e853 in clientReadRequest (fd=37, data=0xc270c8) at client_side.c:4331 conn = (ConnStateData *) 0xc270c8 size = 422 F = (fde *) 0x2a957a68b8 len = 4095 ret = 0 #5 0x004346ad in comm_call_handlers (fd=37, read_event=1, write_event=0) at comm_generic.c:264 hdl = (PF *) 0x42e4e3 clientReadRequest hdl_data = (void *) 0xc270c8 do_read = 1 F = (fde *) 0x2a957a68b8 do_incoming = 1 #6 0x00434f3e in do_comm_select (msec=579) at comm_epoll.c:195 i = 0 num = 1 saved_errno = 11 #7 0x00434a55 in comm_select (msec=579) at comm_generic.c:390 last_timeout = 1260237328.0927789 rc = 0 start = 1260237328.5134871 #8 0x0046722c in main (argc=3, argv=0x7fbfffd798) at main.c:862 errcount = 0 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. But it would not be harmful to make clientProcessBody gracefully handle size_left == 0 I guess. A backtrace would be nice. Regards Henrik -- Mark Nottingham m...@yahoo-inc.com -- Mark Nottingham m...@yahoo-inc.com
Assertion in clientProcessBody
I've got a user tripping across the following assertion in clientProcessBody (2.7): /* Some sanity checks... */ assert(conn-body.size_left 0); conn-body.size_left is 0, and the method is GET; content-length is 226. request_entities is on (obviously). Any thoughts here? Should this really be =, or should clientProcessBody never get a 0 size_left? Cheers, -- Mark Nottingham m...@yahoo-inc.com
Re: Assertion in clientProcessBody
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. But it would not be harmful to make clientProcessBody gracefully handle size_left == 0 I guess. A backtrace would be nice. Regards Henrik
Re: Assertion in clientProcessBody
#2 0x00435749 in xassert (msg=0x4c02f1 conn-body.size_left 0, file=0x4bd9d0 client_side.c, line=4445) at debug.c:505 No locals. #3 0x0042ece1 in clientProcessBody (conn=0xc270c8) at client_side.c:4445 valid = 1 size = 0 buf = 0x81024f0 cbdata = (void *) 0x51703568 callback = (CBCB *) 0x45602f httpRequestBodyHandler request = (request_t *) 0x1ed3c80 #4 0x0042e853 in clientReadRequest (fd=37, data=0xc270c8) at client_side.c:4331 conn = (ConnStateData *) 0xc270c8 size = 422 F = (fde *) 0x2a957a68b8 len = 4095 ret = 0 #5 0x004346ad in comm_call_handlers (fd=37, read_event=1, write_event=0) at comm_generic.c:264 hdl = (PF *) 0x42e4e3 clientReadRequest hdl_data = (void *) 0xc270c8 do_read = 1 F = (fde *) 0x2a957a68b8 do_incoming = 1 #6 0x00434f3e in do_comm_select (msec=579) at comm_epoll.c:195 i = 0 num = 1 saved_errno = 11 #7 0x00434a55 in comm_select (msec=579) at comm_generic.c:390 last_timeout = 1260237328.0927789 rc = 0 start = 1260237328.5134871 #8 0x0046722c in main (argc=3, argv=0x7fbfffd798) at main.c:862 errcount = 0 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. But it would not be harmful to make clientProcessBody gracefully handle size_left == 0 I guess. A backtrace would be nice. Regards Henrik -- Mark Nottingham m...@yahoo-inc.com
