total_time is lower than CURLOPT_TIMEOUT when request timed out

[lukasruzicka]

Using request with CURLOPT_TIMEOUT = 1.
Then request is timed out and total_time is set to 0.204s as showed at output 1.

Without using CURLOPT_TIMEOUT, total_time is set properly as showed at output 2.

Version cURL used: 7.45.0

output 1

time curl -s --max-time 1 -w '\nLookup time:\t%{time_namelookup}\nConnect time:\t%{time_connect}\nPreXfer time:\t%{time_pretransfer}\nStartXfer time:\t%{time_starttransfer}\n\nTotal time:\t%{time_total}\n' -I http://www.url-that-timed-out-in-2-seconds.com

Lookup time:    0.003
Connect time:   0.003
PreXfer time:   0.004
StartXfer time: 0.000

Total time:     0.204

real    0m1.016s
user    0m0.005s
sys     0m0.011s

output 2

time curl -s -w '\nLookup time:\t%{time_namelookup}\nConnect time:\t%{time_connect}\nPreXfer time:\t%{time_pretransfer}\nStartXfer time:\t%{time_starttransfer}\n\nTotal time:\t%{time_total}\n' -I http://www.url-that-timed-out-in-2-seconds.com
HTTP/1.1 200 OK
Server: nginx/1.8.0
Date: Mon, 23 Nov 2015 16:02:50 GMT
Content-Type: text/html
Connection: keep-alive
Vary: Accept-Encoding


Lookup time:    0.003
Connect time:   0.003
PreXfer time:   0.003
StartXfer time: 2.004

Total time:     2.004

real    0m2.018s
user    0m0.006s
sys     0m0.008s

[bagder]

It'd be interesting if you'd add the following on the first case: --trace-ascii log.txt --trace-time and see if you can detect what curl does after the "total time" mark.

[lukasruzicka]

Here is the request:

 time curl -s --max-time 1 --trace-ascii log.txt --trace-time -w '\nLookup time:\t%{time_namelookup}\nConnect time:\t%{time_connect}\nPreXfer time:\t%{time_pretransfer}\nStartXfer time:\t%{time_starttransfer}\n\nTotal time:\t%{time_total}\n' -I http://www.sample-host.com/webtools/timeout.php?time=2

and the result:

14:08:42.143969 == Info:   Trying [sample-public-ipv4]...
14:08:42.146119 == Info: Connected to [www.sample-host.com] ([sample-public-ipv4]) port 80 (#0)
14:08:42.146192 => Send header, 110 bytes (0x6e)
0000: HEAD /webtools/timeout.php?time=2 HTTP/1.1
002c: Host: [www.sample-host.sample]
0046: User-Agent: curl/7.45.0
005f: Accept: */*
006c:
14:08:43.144545 == Info: Operation timed out after 1001 milliseconds with 0 bytes received
14:08:43.144613 == Info: Closing connection 0

...and sorry for accidentaly close and reopen the issue!

[bagder]

Thanks. I've been able to repeat this myself now.

[bagder]

This seems to do the trick. I'll just verify some more before I push:

diff --git a/lib/url.c b/lib/url.c
index feb4517..7ae069f 100644
--- a/lib/url.c
+++ b/lib/url.c
@@ -6045,10 +6045,11 @@ CURLcode Curl_done(struct connectdata **connp,
                    CURLcode status,  /* an error if this is called after an
                                         error was detected */
                    bool premature)
 {
   CURLcode result;
+  CURLcode rc;
   struct connectdata *conn;
   struct SessionHandle *data;

   DEBUGASSERT(*connp);

@@ -6086,11 +6087,12 @@ CURLcode Curl_done(struct connectdata **connp,
   if(conn->handler->done)
     result = conn->handler->done(conn, status, premature);
   else
     result = status;

-  if(!result && Curl_pgrsDone(conn))
+  rc = Curl_pgrsDone(conn);
+  if(!result && rc)
     result = CURLE_ABORTED_BY_CALLBACK;

   if((conn->send_pipe->size + conn->recv_pipe->size != 0 &&
       !data->set.reuse_forbid &&
       !conn->bits.close)) {