[squid-users] large post request fails... comm_write: fd_table[19].rwstate != NULL, httpSendComplete: FD 19: size 0: errflag -9

squid-2.5.STABLE5-42.21 (SuSE RPM) linux 2.4 on big endian.

I have a 10MB POST request that fails when attempting to use the proxy
server. After turning up a bit of logging it looks like squid is using
fd 18 and 19 for this POST request. There is also a 20/21 pair for a
periodic get request...

Messages that might be of interest are "comm_write: fd_table[19].rwstate
!= NULL" and "httpSendComplete: FD 19: size 0: errflag -9"

Do either of these ring any bells or have much meaning to anyone?

This is a bit toward the end of FD 19's activity in cache.log to get a
context...

2004/11/05 14:37:04| comm_poll: FD 19 ready for reading
2004/11/05 14:37:04| httpReadReply: FD 19: len 1348.
2004/11/05 14:37:04| clientSendMoreData:
http://www.dataservicesinc.com/eWorld2/OrderSubmitted.asp?PID=B434150FA3
9F0589, 1348 bytes
2004/11/05 14:37:04| clientSendMoreData: FD 18
'http://www.dataservicesinc.com/eWorld2/OrderSubmitted.asp?PID=B434150FA
39F0589', out.offset=4044
2004/11/05 14:37:04| comm_write: FD 18: sz 1348: hndl 0x41e700: data
0x7e1a98.
2004/11/05 14:37:04| commSetSelect: FD 18 type 2
2004/11/05 14:37:04| httpPconnTransferDone: FD 19
2004/11/05 14:37:04| httpPconnTransferDone: content_length=6549
2004/11/05 14:37:04| commSetTimeout: FD 19 timeout 900
2004/11/05 14:37:04| commSetSelect: FD 19 type 1
2004/11/05 14:37:04| comm_poll: 1+0 FDs ready
2004/11/05 14:37:04| comm_poll: FD 18 ready for writing
2004/11/05 14:37:04| commHandleWrite: FD 18: off 0, sz 1348.
2004/11/05 14:37:04| commHandleWrite: write() returns 1348
2004/11/05 14:37:04| clientWriteComplete: FD 18, sz 1348, err 0, off
5392, len -1
2004/11/05 14:37:04| comm_poll: 1+0 FDs ready
2004/11/05 14:37:04| comm_poll: FD 19 ready for reading
2004/11/05 14:37:04| httpReadReply: FD 19: len 1417.
2004/11/05 14:37:04| clientSendMoreData:
http://www.dataservicesinc.com/eWorld2/OrderSubmitted.asp?PID=B434150FA3
9F0589, 1417 bytes
2004/11/05 14:37:04| clientSendMoreData: FD 18
'http://www.dataservicesinc.com/eWorld2/OrderSubmitted.asp?PID=B434150FA
39F0589', out.offset=5392
2004/11/05 14:37:04| comm_write: FD 18: sz 1417: hndl 0x41e700: data
0x7e1a98.
2004/11/05 14:37:04| commSetSelect: FD 18 type 2
2004/11/05 14:37:04| httpPconnTransferDone: FD 19
2004/11/05 14:37:04| httpPconnTransferDone: content_length=6549
2004/11/05 14:37:04| commSetTimeout: FD 19 timeout -1
2004/11/05 14:37:04| commSetSelect: FD 19 type 1
2004/11/05 14:37:04| comm_remove_close_handler: FD 19, handler=0x43f4c8,
data=0x7dbc28
2004/11/05 14:37:04| comm_remove_close_handler: FD 19, handler=0x42f544,
data=0x7dce50
2004/11/05 14:37:04| commSetSelect: FD 19 type 1
2004/11/05 14:37:04| commSetTimeout: FD 19 timeout 120

Below is the next time FD 19 is mentioned...

2004/11/05 14:37:04| commSetSelect: FD 19 type 1
2004/11/05 14:37:04| commSetTimeout: FD 19 timeout -1
2004/11/05 14:37:04| comm_add_close_handler: FD 19, handler=0x42f544,
data=0x7dce50
2004/11/05 14:37:04| httpStart: "GET
http://www.dataservicesinc.com/eWorld2/Libraries/ServerSide/ASPUpload/ba
r.asp?to=0&PID=B434150FA39F0589"
2004/11/05 14:37:04| comm_add_close_handler: FD 19, handler=0x43f4c8,
data=0x7e7aa0
2004/11/05 14:37:04| httpSendRequest: FD 19: httpState 0x7e7aa0.
2004/11/05 14:37:04| commSetTimeout: FD 19 timeout 86400
2004/11/05 14:37:04| commSetSelect: FD 19 type 1
2004/11/05 14:37:04| httpBuildRequestHeader: Accept: */*
2004/11/05 14:37:04| httpBuildRequestHeader: Referer:
http://www.dataservicesinc.com/eWorld2/Libraries/ServerSide/ASPUpload/fr
amebar.asp?to=10&PID=B434150FA39F0589&b=IE
2004/11/05 14:37:04| httpBuildRequestHeader: Accept-Language: en-us
2004/11/05 14:37:04| httpBuildRequestHeader: Proxy-Connection:
Keep-Alive
2004/11/05 14:37:04| httpBuildRequestHeader: User-Agent: Mozilla/4.0
(compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 1.1.4322)
2004/11/05 14:37:04| httpBuildRequestHeader: Host:
www.dataservicesinc.com
2004/11/05 14:37:04| httpBuildRequestHeader: Pragma: no-cache
2004/11/05 14:37:04| httpBuildRequestHeader: Cookie:
ASPSESSIONIDCCDAASSC=FGLPBMNCJAMPGIDBJIFEOOLJ
2004/11/05 14:37:04| comm_write: FD 19: sz 589: hndl 0x440920: data
0x7e7aa0.
2004/11/05 14:37:04| comm_write: fd_table[19].rwstate != NULL
2004/11/05 14:37:04| commSetSelect: FD 19 type 2
2004/11/05 14:37:05| comm_poll: 1+0 FDs ready
2004/11/05 14:37:05| comm_poll: FD 18 ready for reading
2004/11/05 14:37:05| clientReadRequest: FD 18: reading request...
2004/11/05 14:37:05| commSetSelect: FD 18 type 1
2004/11/05 14:37:05| clientProcessBody: start fd=18 body_size=10540328
in.offset=4095cb=0x420ed4 req=(nil)
2004/11/05 14:37:05| clientProcessBody: start fd=18 body_size=10536233
in.offset=0 cb=0x420ed4 req=(nil)
2004/11/05 14:37:05| clientProcessBody: end fd=18 size=4095
body_size=10536233 in.offset=0 cb=0x420ed4 req=(nil)
2004/11/05 14:37:05| comm_poll: 1+0 FDs ready
2004/11/05 14:37:05| comm_poll: FD 18 ready for reading
2004/11/05 14:37:05| clientReadRequest: FD 18: reading request...
2004/11/05 14:37:05| commSetSelect: FD 18 type 1
2004/11/05 14:37:05| clientProcessBody: start fd=18 body_size=10536233
in.offset=4095 cb=0x420ed4 req=(nil)
2004/11/05 14:37:05| clientProcessBody: start fd=18 body_size=10532138
in.offset=0 cb=0x420ed4 req=(nil)

(next time fd 19 is mentioned)

2004/11/05 14:37:10| comm_poll: FD 20 ready for writing
2004/11/05 14:37:10| comm_remove_close_handler: FD 19, handler=0x42f544,
data=0x7dce50
2004/11/05 14:37:10| comm_close: FD 19
2004/11/05 14:37:10| httpSendComplete: FD 19: size 0: errflag -9.
2004/11/05 14:37:10| commCallCloseHandlers: FD 19
2004/11/05 14:37:10| commCallCloseHandlers: ch->handler=0x43f4c8
2004/11/05 14:37:10| fd_close FD 19
http://www.dataservicesinc.com/eWorld2/Libraries/ServerSide/ASP
2004/11/05 14:37:10| comm_poll: 0+0 FDs ready
2004/11/05 14:37:10| comm_poll: 0+0 FDs ready
2004/11/05 14:37:10| comm_poll: time out: 1099683430.

FD 18 continues for some time after this, but it looks like the POST
data is no longer being sent to the destination. Does anyone have any
ideas about what might be causing this, or what debug section would have
more valuable information?

Thanks for any information,
~ Daniel
Received on Fri Nov 05 2004 - 13:51:39 MST