On Thu, 10 Jan 2013, Yang Tse wrote:

> Attached file logs_7_tests.tar.gz has test traces for test cases 64, 69, 90,
> 153, 160, 1079 and 1095. These http tests have in common that http test
> server is instructed to close connection with 'swsclose', while test case is
> doing more than one request.

Thanks, this is helpful!

Lets focus on the single test 64 first. What's the exact test
target/OS/version etc you're using to trigger this? Does it fail on all runs?

Also, can you show us the log/http_server.log after a run where the test
fails?

Clearly when you run this test case it doesn't properly detect that the
connection is dead when the second request is made and goes on, while in my
end it detects the problem, creates a new connection and everything is fine.
Compare to my log/trace64 piece:

22:34:20.834635 == Info: Ignoring the response-body
22:34:20.835136 <= Recv data, 26 bytes (0x1a)
0000: This is not the real page.
22:34:20.850927 == Info: Connection #0 to host 127.0.0.1 left intact
22:34:20.853020 == Info: Issue another request to this URL:
'http://127.0.0.1:8990/64'
22:34:20.855881 == Info: Found bundle for host 127.0.0.1: 0x780bf58
22:34:20.856924 == Info: Connection 0 seems to be dead!
22:34:20.859015 == Info: Closing connection 0
22:34:20.863244 == Info: The cache now contains 0 members
22:34:20.869979 == Info: About to connect() to 127.0.0.1 port 8990 (#1)
22:34:20.870115 == Info: Trying 127.0.0.1...
22:34:20.870228 == Info: connected
22:34:20.870345 == Info: Connected to 127.0.0.1 (127.0.0.1) port 8990 (#1)
22:34:20.870461 == Info: 0x76955f8 is at send pipe head!
22:34:20.871375 == Info: STATE: CONNECT => DO handle 0x77eb418; line 1025
(connection #1)
22:34:20.892268 == Info: Server auth using Digest with user 'testuser'
22:34:20.893184 => Send header, 222 bytes (0xde)
0000: GET /64 HTTP/1.1
0012: Authorization: Digest username="testuser", realm="testrealm", no
0052: nce="1053604145", uri="/64", response="c55f7f30d83d774a3d2dcacf7
0092: 25abaca"
009c: User-Agent: curl/7.28.2-DEV
00b9: Host: 127.0.0.1:8990
00cf: Accept: */*

... and the log/http_server.log shows this a few milliseconds before:

22:34:20.793753 Sent off 200 bytes
22:34:20.793770 Sent off 45 bytes
22:34:20.793784 Response sent (245 bytes) and written to log/server.response
22:34:20.793794 instructed to close connection after server-reply
22:34:20.793803 ====> Client disconnect 0

Right now I'm leaning towards a problematic test case/test server since this
is code that really isn't affected by my changes - I've just changed some
timing and code flows, not the actual real socket/TCP handling.

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