problem with post request on persistent connections

Hello,

I have problems with a POST request in the following situation:

Do a request to a server with a persistent connection.
Wait for the server to close the TCP connection.
Do a POST request to the same server.

This POST request fails. With tcpdump I can see that the headers of the POST
request are written to the socket that is already closed by the server
before this socket is closed by lib-www. After this a new connection to the
webserver is made but only the headers of the POST request are send via this
connection.  The webserver keeps waiting for the body of the POST request
and after a while it times out.
Below some tracing is included.

Does anybody know what is going wrong?

Mark Horsthuis
 
E-mail: Mark.Horsthuis@cmg.nl <mailto:Mark.Horsthuis@cmg.nl> 
 

Request..... Created 1400fd000
HTSimplify.. `http://10.16.247.29:8096/perl/post.pl' into
............ `http://10.16.247.29:8096/perl/post.pl'
Tmp Anchor.. With location `file:/tmp/BAAaasfta.959600626.1'
HTSimplify.. `file:/tmp/BAAaasfta.959600626.1' into
............ `file:/tmp/BAAaasfta.959600626.1'
ChunkStream. Chunk 1400deb60 created with max size 0
HTAccess.... Accessing document http://10.16.247.29:8096/perl/post.pl
Net Before.. calling 3000480e590 (request 1400fd000, context 0)
Net Object.. 1400cbcc0 created with hash 3
Net Object.. starting request 1400fd000 (retry=1) with net object 1400cbcc0
HTTP........ Looking for `http://10.16.247.29:8096/perl/post.pl'
HTHost parse Looking up `10.16.247.29' on port 8096
Host info... REUSING CHANNEL 1400c1040
Host info... Added Net 1400cbcc0 (request 1400fd000) to pipe on Host
1400cb400, 4 requests made, 1 requests in pipe, 0 pending
Timer....... Deleted active timer 1400c11c0
HTHost...... No ActivateRequest callback handler registered
Channel..... Semaphore increased to 1 for channel 1400c1040
Host connect Unlocking Host 1400cb400
StreamStack. Constructing stream stack for text/x-http to */*
Tee......... Created stream 1400c0f20 with resolver 3000a005a40
HTTP........ Dumping response to `w3chttp.out'
Tee......... Created stream 1400c11f0 with resolver 3000a005a40
HTTP........ Dumping request to `w3chttp.out'
HTTP........ Generating HTTP/1.x Request Headers
HTTPGen..... Extra local
HTTP........ Generating General Headers
MIME........ Generating Entity Headers
Buffer...... Flushing 140014870
Write Socket 496 bytes written to 11
Timer....... Created one shot timer 1400c12e0 with callback 3000780d4d0,
context 1400dedc0, and relative timeout 21
Uploading... Holding 1400dedc0 for 21 ms using time 1400c12e0
Event....... Register socket 11, request 1400fd000 handler 3000c816920 type
HTEvent_READ at priority 20
Event....... Registering socket for HTEvent_READ
Timer....... Found timer 1400c1220 with callback 3000480cf60, context
1400de8c0, and relative timeout 120000
Read Socket. FIN received on socket 11
Timer....... Deleted active timer 1400c1220
Event....... No more events registered for socket 11
Event....... Reset MaxSock from 11 to 1
Event....... Socket 11 unregistered for HTEvent_READ
Event....... Couldn't find socket 11. Can't unregister type HTEvent_WRITE
Host recovered 1 times. Moving 1 Net objects from pipe line to pending queue
Event....... Couldn't find socket 11. Can't unregister type HTEvent_READ
Event....... Couldn't find socket 11. Can't unregister type HTEvent_WRITE
Host recover Resetting net object 1400cbcc0
HTTP Clean.. Called with status -904, net 1400cbcc0
HTTPGen..... ABORTING...
HTTPRequest. ABORTING...
Buffer...... ABORTING...
FileWriter.. ABORTING...
MIMERequest. ABORTING...
Timer....... Deleted active timer 1400c12e0
Channel..... Semaphore set to 0 for channel 1400c1040
Event....... Couldn't find socket 11. Can't unregister type HTEvent_READ
Event....... Couldn't find socket 11. Can't unregister type HTEvent_WRITE
Channel..... Delete 1400c1040 with semaphore 0
Buffer...... ABORTING...
Socket read. FREEING....
Socket write FREEING....
Net Manager. Decreasing active sockets to 0, 1 persistent sockets
Channel..... Deleted 1400c1040, socket 11
Net Manager. 0 active sockets, decreasing persistent sockets to 0
Host info... removed host 1400cb400 as persistent
Host has 1 object(s) pending - attempting launch
Host info... Popping 1400cbcc0 from pending net queue on host 1400cb400
HTHost...... No ActivateRequest callback handler registered
Launch pending net object 1400cbcc0 with 0 reqs in pipe (0 reqs made)
Net Object.. 1400cbcc0 calling 3000780d6b0 with event type 65544 and context
1400dedc0
Host info... Added Net 1400cbcc0 (request 1400fd000) to pipe on Host
1400cb400, 1 requests made, 1 requests in pipe, 0 pending
HTHost...... No ActivateRequest callback handler registered
HTHost 1400cb400 going to state TCP_CHANNEL.
HTHost 1400cb400 going to state TCP_DNS.
ParseInet... as port 8096 on 10.16.247.29 with 1 homes
HTHost 1400cb400 going to state TCP_NEED_SOCKET.
Socket...... Created 11
Net Manager. Increasing active sockets to 1, 0 persistent sockets
Socket...... Turned off Nagle's algorithm
Socket...... Non-blocking socket
Channel..... Hash value is 11
Channel..... Added 1400c1040 to list 1400284a0
Reader...... Created reader stream 1400e2800
Socket...... TCP send buffer size is 32768 for socket 11
HTHost 1400cb400 going to state TCP_NEED_CONNECT.
HTDoConnect. WOULD BLOCK `10.16.247.29'
Event....... Register socket 11, request 1400fd000 handler 3000c816920 type
HTEvent_CONNECT at priority 20
Event....... Registering socket for HTEvent_CONNECT
Event....... New value for MaxSock is 11
Timer....... Created repetitive timer 1400c12e0 with callback 3000480cf60,
context 1400defc0, and relative timeout 120000
Timer....... Created repetitive timer 1400c1490 with callback 120015380,
context 0, and relative timeout 1000
Timer....... Found timer 1400c1490 with callback 120015380, context 0, and
relative timeout 1000
Timer....... Dispatch timer 1400c1490
Event Loop.. calling select: maxfds is 11
............ READ :
............ WRITE: 11
............ OOB  :
............ Timeout is 1 s, 0 microsecs
Event Loop.. select returns 1
............ READ :
............ WRITE: 11
............ OOB  :
............ Timeout is 1 s, 0 microsecs
Timer....... Found timer 1400c12e0 with callback 3000480cf60, context
1400defc0, and relative timeout 120000
EventOrder.. execute ordered events
EventList... calling socket 11, request 1400fd000 handler 3000c816920 type
HTEvent_WRITE
Host Event.. WRITE passed to `http://10.16.247.29:8096/perl/post.pl'
HTHost 1400cb400 going to state TCP_CONNECTED.
Timer....... Deleted active timer 1400c12e0
Event....... No more events registered for socket 11
Event....... Reset MaxSock from 11 to 1
Event....... Socket 11 unregistered for HTEvent_CONNECT
HTHost 1400cb400 connected.
Host connect Unlocking Host 1400cb400
Tee......... Created stream 1400c12e0 with resolver 3000a005a40
HTTP........ Dumping request to `w3chttp.out'
Host Event.. FLUSH passed to `http://10.16.247.29:8096/perl/post.pl'
HTTP........ Generating HTTP/1.x Request Headers
HTTPGen..... Extra local
HTTP........ Generating General Headers
MIME........ Generating Entity Headers
Buffer...... Flushing 140014870
Write Socket 496 bytes written to 11
Read Socket. WOULD BLOCK fd 11
Event....... Register socket 11, request 1400fd000 handler 3000c816920 type
HTEvent_READ at priority 20
Event....... Registering socket for HTEvent_READ
Event....... New value for MaxSock is 11
Timer....... Created repetitive timer 1400c1220 with callback 3000480cf60,
context 1400dc600, and relative timeout 120000
Event Loop.. calling select: maxfds is 11
............ READ : 11
............ WRITE:
............ OOB  :
............ Timeout is 0 s, 912000 microsecs
Event Loop.. select returns 0
............ READ :
............ WRITE:
............ OOB  :
............ Timeout is 0 s, 912000 microsecs
Timer....... Found timer 1400c1490 with callback 120015380, context 0, and
relative timeout 1000
Timer....... Dispatch timer 1400c1490
Event Loop.. calling select: maxfds is 11
............ READ : 11
............ WRITE:
............ OOB  :
............ Timeout is 1 s, 0 microsecs
Event Loop.. select returns 0
............ READ :
............ WRITE:
............ OOB  :
............ Timeout is 1 s, 0 microsecs
Timer....... Found timer 1400c1490 with callback 120015380, context 0, and
relative timeout 1000
Timer....... Dispatch timer 1400c1490
Event Loop.. calling select: maxfds is 11
............ READ : 11
............ WRITE:
............ OOB  :
............ Timeout is 1 s, 0 microsecs
Event Loop.. select returns 0
............ READ :
............ WRITE:
............ OOB  :
............ Timeout is 1 s, 0 microsecs
Timer....... Found timer 1400c1490 with callback 120015380, context 0, and
relative timeout 1000
Timer....... Dispatch timer 1400c1490
Event Loop.. calling select: maxfds is 11
............ READ : 11
............ WRITE:
............ OOB  :
............ Timeout is 1 s, 0 microsecs
Event Loop.. select returns 0
............ READ :
............ WRITE:
............ OOB  :
............ Timeout is 1 s, 0 microsecs
Timer....... Found timer 1400c1490 with callback 120015380, context 0, and
relative timeout 1000
Timer....... Dispatch timer 1400c1490 

Received on Monday, 29 May 2000 09:01:22 UTC