Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

total_time is lower than CURLOPT_TIMEOUT when request timed out #538

Closed
lukasruzicka opened this issue Nov 23, 2015 · 4 comments
Closed

total_time is lower than CURLOPT_TIMEOUT when request timed out #538

lukasruzicka opened this issue Nov 23, 2015 · 4 comments
Assignees
@bagder

Comments

@lukasruzicka
Copy link

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
Copy link
Member

bagder commented Nov 24, 2015

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 lukasruzicka reopened this Nov 24, 2015
@lukasruzicka
Copy link
Author

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
Copy link
Member

bagder commented Nov 24, 2015

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

@bagder bagder self-assigned this Nov 24, 2015
@bagder
Copy link
Member

bagder commented Nov 24, 2015

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)) {

@bagder bagder closed this as completed in 40c349a Nov 24, 2015
@lock lock bot locked as resolved and limited conversation to collaborators May 7, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@bagder bagder

Labels
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@bagder @lukasruzicka