On Fri, 11 Jan 2013, Yang Tse wrote:

> I'll study your trace, compare with mine and later on start to debug this.
>
> Just wanted now to handle you all logs for test 64.

Can you first check and see if there's a time descripancy between the trace64
log and the http_server.log ? I can't make sense of the times in there:

http server:

00:25:55.470998 ====> Client connect
00:25:55.470998 TCP_NODELAY set
00:25:55.470998 accept_connection 3 returned 4
00:25:55.470998 accept_connection 3 returned 0
00:25:55.490998 Read 84 bytes
00:25:55.490998 Process 84 bytes request
00:25:55.490998 Got request: GET /64 HTTP/1.1

trace:

00:25:55.461476 == Info: About to connect() to 127.0.0.1 port 8990 (#0)
00:25:55.471476 == Info: Trying 127.0.0.1...
00:25:55.491476 == Info: connected
00:25:55.491476 == Info: Connected to 127.0.0.1 (127.0.0.1) port 8990 (#0)
00:25:55.491476 == Info: 0xb4f1a0 is at send pipe head!
00:25:55.491476 == Info: STATE: CONNECT => DO handle 0xb72f68; line 1025
(connection #0)
00:25:55.491476 == Info: Server auth using Digest with user 'testuser'
00:25:55.491476 => Send header, 84 bytes (0x54)

See? The server claims it got the GET already before libcurl logged
'connected' !

And then for the next sequence of interest to me:

server log:

00:25:55.510998 Response sent (245 bytes) and written to log/server.response
00:25:55.510998 instructed to close connection after server-reply
00:25:55.510998 ====> Client disconnect 0

trace log:

00:25:55.511476 == Info: Connection #0 to host 127.0.0.1 left intact
00:25:55.511476 == Info: Issue another request to this URL:
'http://127.0.0.1:8990/64'
00:25:55.511476 == Info: Found bundle for host 127.0.0.1: 0xb7c180
00:25:55.511476 == Info: Re-using existing connection! (#0) with host
127.0.0.1
00:25:55.511476 == Info: Connected to 127.0.0.1 (127.0.0.1) port 8990 (#0)

... which looks like SocketIsDead() didn't think the connection it tries to
re-use is dead, but the time stamps indicate it should've seen it.

Then there's clearly a bug when things went south due to the dead connection
being attempted for sending the request on:

00:25:55.571476 == Info: Recv failure: Connection reset by peer
00:25:55.571476 == Info: Connection died, retrying a fresh connect
00:25:55.571476 == Info: Recv failure: Connection reset by peer
00:25:55.571476 == Info: Connection died, retrying a fresh connect

... it doesn't look like this is truly trying a fresh connect, it seems to
mostly just _say_ it!

-- 
  / daniel.haxx.se
-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette:  http://curl.haxx.se/mail/etiquette.html