From: Mykyta Dorokhin <kit-d_at_ukr.net>
Date: Tue, 08 Feb 2011 11:11:59 +0200

('binary' encoding is not supported, stored as-is) ('binary' encoding is not supported, stored as-is)  Hello,

   I noticed that sometimes curl_perform takes more time then had been
   set by curl_easy_setopt(CURLOPT_TIMEOUT);

   Here is my short log:
   [07/02/11 15:54:25-T8] Send:513 info : Send a request. Connect t/o=30.
   Message t/o=45. Fresh not requested
   [07/02/11 15:54:25-T8] LibcurlTrace:176 debug : * About to connect()
   to test.test.com port 443 (#0)
   [07/02/11 15:54:25-T8] LibcurlTrace:176 debug : * Trying x.x.x.x...
   [07/02/11 15:54:27-T8] LibcurlTrace:176 debug : * SSLv3, TLS
   handshake, Server hello (2):
   [07/02/11 15:54:27-T8] LibcurlTrace:176 debug : * SSLv3, TLS change
   cipher, Client hello (1):
   [07/02/11 15:54:27-T8] LibcurlTrace:176 debug : * SSLv3, TLS
   handshake, Finished (20):
   [07/02/11 15:54:27-T8] LibcurlTrace:176 debug : * SSLv3, TLS change
   cipher, Client hello (1):
   [07/02/11 15:54:27-T8] LibcurlTrace:176 debug : * SSLv3, TLS
   handshake, Finished (20):
   [07/02/11 15:54:27-T8] LibcurlTrace:176 debug : * SSL connection using
   RC4-MD5
   [07/02/11 15:54:27-T8] LibcurlTrace:176 debug : * Server certificate:
   ...
   [07/02/11 15:54:27-T8] LibcurlTrace:176 debug : * SSL certificate
   verify ok.
   [07/02/11 15:54:27-T8] LibcurlTrace:170 debug : > GET /test.aspx
   HTTP/1.1
   Host: test.test.com
   Accept: */*
   ...
   ...
   [07/02/11 15:55:12-T8] LibcurlTrace:176 debug : * Operation timed out
   after 45000 milliseconds with 0 bytes received
   [07/02/11 15:55:12-T8] LibcurlTrace:176 debug : * Closing connection
   #0
   [07/02/11 15:55:12-T8] LibcurlTrace:176 debug : * SSLv3, TLS alert,
   Client hello (1):
   [07/02/11 15:55:12-T8] LibcurlTrace:176 debug : * Timeout was reached
   [07/02/11 15:55:12-T8] PrintSessionInfo:341 debug : ===== Last HTTP
   Session Info =================
   [07/02/11 15:55:12-T8] PrintSessionInfo:344 debug :
   CURLINFO_NAMELOOKUP_TIME=0.007205
   [07/02/11 15:55:12-T8] PrintSessionInfo:347 debug :
   CURLINFO_CONNECT_TIME=0.796720
   [07/02/11 15:55:12-T8] PrintSessionInfo:354 debug :
   CURLINFO_PRETRANSFER_TIME=2.468439
   [07/02/11 15:55:12-T8] PrintSessionInfo:357 debug :
   CURLINFO_STARTTRANSFER_TIME=0.000000
   [07/02/11 15:55:12-T8] PrintSessionInfo:360 debug :
   CURLINFO_TOTAL_TIME=47.521797
   [07/02/11 15:55:12-T8] PrintSessionInfo:363 debug :
   CURLINFO_REDIRECT_TIME=0.000000
   [07/02/11 15:55:12-T8] PrintSessionInfo:366 debug :
   CURLINFO_SIZE_DOWNLOAD=0.000000
   [07/02/11 15:55:12-T8] PrintSessionInfo:369 debug :
   CURLINFO_SIZE_UPLOAD=0.000000
   [07/02/11 15:55:12-T8] PrintSessionInfo:372 debug :
   CURLINFO_SPEED_DOWNLOAD=0.000000
   [07/02/11 15:55:12-T8] PrintSessionInfo:375 debug :
   CURLINFO_SPEED_UPLOAD=0.000000

   So, even though it claims that the request timed out after 45000
   milliseconds but in fact it took 47.5 seconds.
   How could it be?

   The "Operation timed out after ...." message is printed from
   Curl_readwrite() when (Curl_tvdiff(k->now, k->start) >=
   data->set.timeout).
   I expected that k->start will be set at the very beginning of the
   curl_perform() but looks like it is not so.

   BTW: I use libcurl 7.20.0, Linux, application is running on GSM modem.
   The issue reproduces about 2-3 % of requests.
   The same behavior observed with the latest 7.21.3 version.

   Could you please check this out? Thanks.

   Mykyta.

('binary' encoding is not supported, stored as-is) -------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html
Received on 2011-02-08