Hi. I think I've found a bug.

When a request uses digest authentication and receives a 401
challenge, cURL fails to compute the timeout periods correctly on
subsequent timeout check events, and thus when the request actually
does timeout without a response, either no timeout event (ever) or a
very late timeout event occurs.

The problem occurs when using the curl_multi_socket_action() interface
to drive cURL via specific events on a per file descriptor and timeout
basis. It may or may not exhibit itself when cURL is driven in other
ways. The curl command-line tool, for example, does not exhibit the
problem. This problem still seems to exist in curl-7.35.0 (but I did
most of my testing with curl-7.34.0).

Here's the output from the attached test.c program, which drives curl
with curl_multi_socket_action() against a test CGI script (also
provided in test.c) that handles a digest request such that the second
half times out. (Please pardon the changed IPs and hostnames.)

Timeout changed to 1 ms
poll() on 0 fds for 1 ms
call curl_multi_socket_action() for timeout
* Adding handle: conn: 0x1281ea8
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x1281ea8) send_pipe: 1, recv_pipe: 0
Add fd=3 events=1
Timeout changed to 3433 ms
poll() on 1 fds for 3433 ms
call curl_multi_socket_action() fd=3 revents=1
Remove fd=3
* About to connect() to server port 80 (#0)
* Trying 1.2.3.4...
Add fd=3 events=4
poll() on 1 fds for 3433 ms
call curl_multi_socket_action() fd=3 revents=4
* Connected to server (1.2.3.4) port 80 (#0)
* Server auth using Digest with user 'user'
> GET /test.cgi?timeout=1000 HTTP/1.1
Host: server
Accept: */*

Change fd=3 events=1
poll() on 1 fds for 3433 ms
call curl_multi_socket_action() fd=3 revents=1
< HTTP/1.1 401 Authorization Required
< Date: Wed, 29 Jan 2014 16:12:58 GMT
* Server Apache/2.2.22 (Debian) is not blacklisted
< Server: Apache/2.2.22 (Debian)
< WWW-Authenticate: Digest realm="test", qop="auth", nonce="thisISaNONCE"
< X-This-Is-The-401: yes
< Vary: Accept-Encoding
< Transfer-Encoding: chunked
<
* Ignoring the response-body
* Connection #0 to host server left intact
* Issue another request to this URL: 'http://server/test.cgi?timeout=1000'
* Found bundle for host server: 0x1282528
* Re-using existing connection! (#0) with host server
* Connected to server (1.2.3.4) port 80 (#0)
* Adding handle: conn: 0x1281ea8
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0x1281ea8) send_pipe: 1, recv_pipe: 0
* Server auth using Digest with user 'user'
> GET /test.cgi?timeout=1000 HTTP/1.1
Authorization: Digest username="user", realm="test", nonce="thisISaNONCE", uri="/test/cgi?timeout=1000", cnonce="ICAgICAgICAgICAgICAgICAgICAgICAgICA2NzIwNzc=", nc=00000001, qop=auth, response="b3ee41c01cd1a1344c9e8ae4f88ccdc3"
Host: server
Accept: */*

Timeout changed to 2915 ms
poll() on 1 fds for 2915 ms
call curl_multi_socket_action() for timeout
Timeout changed to 1558 ms
poll() on 1 fds for 1558 ms
call curl_multi_socket_action() for timeout
Timeout changed to 295223 ms
poll() on 1 fds for 295223 ms
...

The timeout is missed here. It should have happend at the "1558 ms"
check.

The program runs until the DNS timer happens to expire, at which time
cURL does check for timeout events on the handle and completes the
request as a timeout very, very late. If, for whatever reason, no DNS
request is necessary or no DNS timer is started, the request will
_never_ time out.

I think the problem stems from the request start time being reset when
the second attempt is made after an internally-handled 401 response.
I've prepared a patch (attached; against 7.35.0) which appears to fix
the issue, but I am not certain it is correct.

Here's the output of the test program when run against a patched
version of cURL:

Timeout changed to 1 ms
poll() on 0 fds for 1 ms
call curl_multi_socket_action() for timeout
* Adding handle: conn: 0xa68ea8
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0xa68ea8) send_pipe: 1, recv_pipe: 0
Add fd=3 events=1
Timeout changed to 3433 ms
poll() on 1 fds for 3433 ms
call curl_multi_socket_action() fd=3 revents=1
Remove fd=3
* About to connect() to server port 80 (#0)
* Trying 1.2.3.4...
Add fd=3 events=4
poll() on 1 fds for 3433 ms
call curl_multi_socket_action() fd=3 revents=4
* Connected to server (1.2.3.4) port 80 (#0)
* Server auth using Digest with user 'user'
> GET /test.cgi?timeout=1000 HTTP/1.1
Host: server
Accept: */*

Change fd=3 events=1
poll() on 1 fds for 3433 ms
call curl_multi_socket_action() fd=3 revents=1
< HTTP/1.1 401 Authorization Required
< Date: Wed, 29 Jan 2014 16:09:41 GMT
* Server Apache/2.2.22 (Debian) is not blacklisted
< Server: Apache/2.2.22 (Debian)
< WWW-Authenticate: Digest realm="test", qop="auth", nonce="thisISaNONCE"
< X-This-Is-The-401: yes
< Vary: Accept-Encoding
< Transfer-Encoding: chunked
<
* Ignoring the response-body
* Connection #0 to host server left intact
* Issue another request to this URL: 'http://server/test.cgi?timeout=1000'
* Found bundle for host server: 0xa69528
* Re-using existing connection! (#0) with host server
* Connected to server (1.2.3.4) port 80 (#0)
* Adding handle: conn: 0xa68ea8
* Adding handle: send: 0
* Adding handle: recv: 0
* Curl_addHandleToPipeline: length: 1
* - Conn 0 (0xa68ea8) send_pipe: 1, recv_pipe: 0
* Server auth using Digest with user 'user'
> GET /test.cgi?timeout=1000 HTTP/1.1
Authorization: Digest username="user", realm="test", nonce="thisISaNONCE", uri="/test.cgi?timeout=1000", cnonce="ICAgICAgICAgICAgICAgICAgICAgICAgICA2MTc3MDA=", nc=00000001, qop=auth, response="c54c8f2da8ffa2ea651075c0c2c4e04e"
Host: server
Accept: */*

Timeout changed to 2969 ms
poll() on 1 fds for 2969 ms
call curl_multi_socket_action() for timeout
Timeout changed to 1559 ms
poll() on 1 fds for 1559 ms
call curl_multi_socket_action() for timeout
* Operation timed out after 5042 milliseconds with 0 out of -1 bytes received
Remove fd=3
Timeout changed to 295157 ms
* Closing connection 0
Timeout changed to -1 ms

Note the timeout check after the "1559 ms" line. This check finds the
timer expired. In the failure case, the timer check happens at the
right time, but it incorrectly compares against the later (second
request) start time and thus finds the timer not expired. Only if
another timer happens to run against the same handle later will it
eventually time out, too late. In cases where there is no DNS lookup,
there may be no such timer, this can lead to a "leaked" handle.

Also note that setting the request timeout too short (less than about
3 seconds) will often lead to the timeouts happening as a result of
other "early" timeout checks that cURL uses to get things going during
the early request phase. The attached test.c program uses 5 seconds,
which is long enough for the second request to start and all the
"early" timers to be finished.

I don't know enough about cURL's internals to tell if the attached
patch breaks anything else, but from what I could tell, that timestamp
is only used for these timeouts and the progress bar.

Thoughts?

-- 
Brad Spencer

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