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
/* This test case is based on several cURL example programs, adapted to show
the "no timeout" issue by using the curl_multi_socket_action() interface.
It's intended to be as simple as possible to show the issue, not to be a
robust or efficient implementation.
This program expects to connect to the following CGI script running under
Apache 2.2:
#!/usr/bin/perl -t
#
# Iff $QUERY_STRING is of the form "timeout=N", where N is a decimal integer,
# then when an Authorization headers exists in the request, this will sleep
# N seconds before returning the 200 OK response.
#
use strict;
use warnings;
use MIME::Base64;
# Do we have an Authorization header?
my $header = $ENV{HTTP_AUTHORIZATION} || '';
if($header eq '') {
# No, so issue a challenge.
print("Status: 401\r\n");
print("WWW-Authenticate: Digest ",
"realm=\"test\", ",
"qop=\"auth\", ",
"nonce=\"thisISaNONCE\"\r\n");
print("X-This-Is-The-401: yes\r\n");
print("\r\n");
print("This is the 401.\n");
exit(0);
}
# Yes, they have passed the AUTHORIZATION header.
#
# If there's a timeout, wait for it.
my $request = $ENV{QUERY_STRING} || '';
if($request =~ /^timeout=(\d+)$/) {
sleep($1);
}
# Echo their header back to them.
print("Content-Type: text/plain\r\n\r\n$header");
exit(0);
The following Apache configuration snippet allows the CGI to run and access
to the Authorization header:
<Directory /var/www/>
AllowOverride None
Options ExecCGI -MultiViews +SymLinksIfOwnerMatch
Order allow,deny
Allow from all
# Run all of the files as CGIs.
<Files "*">
SetHandler cgi-script
</Files>
# Expose the Authorization header to the CGIs.
RewriteEngine on
RewriteCond %{HTTP:Authorization} ^(.*)
RewriteRule .* - [e=HTTP_AUTHORIZATION:%1]
</Directory>
*/
#include <stdio.h>
#include <string.h>
#include <poll.h>
#include <assert.h>
#include <errno.h>
#include <curl/curl.h>
/* The URL of the test CGI script, minus query arguments. */
#define TEST_URL "http://server/test.cgi";
/* Enough room for some test fds */
struct pollfd fds[100];
/* The number of fds we are using in the array. */
int fd_count = 0;
/* Called when cURL changes the fd list */
static int sock_cb(CURL *e, curl_socket_t s, int what, void *cbp, void *sockp)
{
int i;
/* Convert events */
short events = 0;
switch(what) {
case CURL_POLL_NONE: events = 0; break;
case CURL_POLL_IN: events = POLLIN; break;
case CURL_POLL_OUT: events = POLLOUT; break;
case CURL_POLL_INOUT: events = POLLIN | POLLOUT; break;
case CURL_POLL_REMOVE: /* We'll remove */ break;
}
/* Find */
for(i = 0; i < fd_count; ++i) {
if(fds[i].fd == s) {
/* Remove? */
if(what == CURL_POLL_REMOVE) {
printf("Remove fd=%d\n", s);
memcpy(fds + i + 1, fds + i, sizeof(fds[0]) * fd_count - i - 1);
--fd_count;
return 0;
}
/* Change */
printf("Change fd=%d events=%x\n", s, events);
fds[i].events = events;
return 0;
}
}
/* Add */
assert(i < sizeof(fds) / sizeof(fds[0]));
printf("Add fd=%d events=%x\n", s, events);
fds[i].fd = s;
fds[i].events = events;
++fd_count;
return 0;
}
/* poll() timeout */
long timeout = -1;
/* Called when cURL changes the timeout */
static int multi_timer_cb(CURLM *multi, long timeout_ms, void *ignored)
{
timeout = timeout_ms;
printf("Timeout changed to %ld ms\n", timeout);
return 0;
}
/*
* Demonstrate the issue.
*/
int main(void)
{
CURL *http_handle;
CURLM *multi_handle;
int remaining;
curl_global_init(CURL_GLOBAL_DEFAULT);
http_handle = curl_easy_init();
/* Create the test request for digest auth. The server will respond with a
401 and cURL will retry with the credentials but then the server will not
respond to that second request (for 1000 seconds) to demonstrate that
cURL doesn't detect the timeout. */
curl_easy_setopt(http_handle, CURLOPT_URL, TEST_URL "?timeout=1000");
curl_easy_setopt(http_handle, CURLOPT_VERBOSE, 1L);
curl_easy_setopt(http_handle, CURLOPT_USERNAME, "user");
curl_easy_setopt(http_handle, CURLOPT_PASSWORD, "password");
curl_easy_setopt(http_handle, CURLOPT_HTTPAUTH, CURLAUTH_DIGEST);
/* Set a short (but not too short) timeout to demonstrate the error. */
curl_easy_setopt(http_handle, CURLOPT_TIMEOUT_MS, 5000L);
/* Create the multi */
multi_handle = curl_multi_init();
/* Set up for curl_multi_socket_action() use */
curl_multi_setopt(multi_handle, CURLMOPT_SOCKETFUNCTION, sock_cb);
curl_multi_setopt(multi_handle, CURLMOPT_TIMERFUNCTION, multi_timer_cb);
/* add the individual transfers */
curl_multi_add_handle(multi_handle, http_handle);
/* loop */
do {
int i;
const int actual_fd_count = fd_count;
struct pollfd actual[100];
/* To keep the example logic simple, just copy everything before we call
poll() so the callbacks can change the array however they want. */
memcpy(actual, fds, sizeof(fds[0]) * fd_count);
printf("poll() on %d fds for %ld ms\n", actual_fd_count, timeout);
const int result = poll(actual, actual_fd_count, timeout);
if(result == -1 && errno != EINTR) {
printf("poll() fails: %s\n", strerror(errno));
return 1;
}
/* dispatch timeout */
if(result == 0) {
printf("call curl_multi_socket_action() for timeout\n");
const CURLMcode result =
curl_multi_socket_action(multi_handle, CURL_SOCKET_TIMEOUT, 0,
&remaining);
if(result != CURLM_OK) {
printf("curl_multi_socket_action() timeout failed: %d\n", result);
return 2;
}
}
/* dispatch events */
else {
for(i = 0; i < actual_fd_count; ++i) {
if(actual[i].revents) {
const int fd = actual[i].fd;
int mask = 0;
if(actual[i].revents & POLLIN) {
mask |= CURL_CSELECT_IN;
}
if(actual[i].revents & POLLOUT) {
mask |= CURL_CSELECT_OUT;
}
if(actual[i].revents & (POLLHUP | POLLERR)) {
mask |= CURL_CSELECT_ERR;
}
printf("call curl_multi_socket_action() fd=%d revents=%x\n", fd,
actual[i].revents);
const CURLMcode result =
curl_multi_socket_action(multi_handle, fd, mask, &remaining);
if(result != CURLM_OK) {
printf("curl_multi_socket_action() fd=%d failed: %d\n", fd, result);
return 3;
}
}
}
}
} while(remaining);
curl_multi_remove_handle(multi_handle, http_handle);
curl_easy_cleanup(http_handle);
curl_multi_cleanup(multi_handle);
curl_global_cleanup();
return 0;
}
--- lib/multi.c.orig 2014-02-04 11:26:11.160052078 -0400
+++ lib/multi.c 2014-02-04 11:32:11.425026700 -0400
@@ -1029,8 +1029,17 @@
break;
case CURLM_STATE_CONNECT:
+ /* Don't set the STARTSINGLE t_startsingle time if we are just
+ re-starting the request (for the second phase of Digest
+ authentication, for example). All of the handle's timeouts are based
+ off the original t_startsingle, and if we change it, the
+ already-scheduled timer events will fire before enough seconds have
+ elapsed (as measured from t_startsingle), and the timeouts won't
+ happen! */
+ if(data->progress.t_startsingle.tv_sec == 0
+ && data->progress.t_startsingle.tv_usec == 0)
+ Curl_pgrsTime(data, TIMER_STARTSINGLE);
/* Connect. We want to get a connection identifier filled in. */
- Curl_pgrsTime(data, TIMER_STARTSINGLE);
data->result = Curl_connect(data, &data->easy_conn,
&async, &protocol_connect);
if(CURLE_NO_CONNECTION_AVAILABLE == data->result) {
-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html
