Bugs item #3061535, was opened at 2010-09-08 00:05
Message generated for change (Settings changed) made by bagder
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=100976&aid=3061535&group_id=976

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: http
Group: wrong behaviour
Status: Open
>Resolution: Fixed
Priority: 5
Private: No
Submitted By: Rodric Glaser (rodricg)
Assigned to: Daniel Stenberg (bagder)
Summary: CURLOPT_TIMEOUT

Initial Comment:
Curl will not abort the operation until <connect time> + CURLOPT_TIMEOUT.

Testing this is a bit involved. I am using:
- The attached multi.php script which hits http://127.0.0.1:82/
- http://127.0.0.1:82/index.php which just sleeps
- The delay-net.pl from http://people.redhat.com/berrange/notes/network-delay.html with a 1.5 second delay
- To delay the initial connect the rule: iptables -I INPUT -i lo -p tcp -m tcp --dport 82 --syn -j QUEUE

Running multi.php then results in:
>php -f "multi.php"
Resource id #5: 28 (Operation timed out after 2000 milliseconds with 0 bytes received)
TotalTime: 3.5011 seconds

I gather this is not the expected behavior based on http://curl.haxx.se/mail/lib-2010-06/0087.html

I have yet to test this with a non php client (my c is rusty) but I have seen the same behavior with:
- curl 7.19.7 (ubuntu php)
- curl 7.20.1 (sabayon php)
- curl 7.21.1 (manual compile)

----------------------------------------------------------------------

>Comment By: Daniel Stenberg (bagder)
Date: 2010-09-17 23:14

Message:
I managed to repeat it thanks to your GREAT recipe, and I found no less
than three places with errors! I've fixed them, commited and pushed my
changes to the git repo.

I'm now awaiting you to try out the latest git to see if you can spot any
further similar problems!

----------------------------------------------------------------------

Comment By: Daniel Stenberg (bagder)
Date: 2010-09-16 09:06

Message:
Right, I misunderstood the problem - I thought it was the connect timeout
while you're talking about the regular timeout after a slow connect. I'll
get back to my chambers and try some more.

----------------------------------------------------------------------

Comment By: Rodric Glaser (rodricg)
Date: 2010-09-16 00:44

Message:
Just tried with a fresh git clone and got the same behavior:

$ time /opt/usr/bin/curl -v --trace-time --connect-timeout 4 --max-time 6
http://127.0.0.1:82/
15:40:24.153545 * About to connect() to 127.0.0.1 port 82 (#0)
15:40:24.153625 * Trying 127.0.0.1... connected
15:40:25.654769 * Connected to 127.0.0.1 (127.0.0.1) port 82 (#0)
15:40:25.654841 > GET / HTTP/1.1
15:40:25.654841 > User-Agent: curl/7.21.2-DEV (x86_64-unknown-linux-gnu)
libcurl/7.21.2-DEV OpenSSL/0.9.8k zlib/1.2.3.3
15:40:25.654841 > Host: 127.0.0.1:82
15:40:25.654841 > Accept: */*
15:40:25.654841 >
15:40:31.655404 * Operation timed out after 6000 milliseconds with 0 bytes
received
15:40:31.655468 * Closing connection #0
curl: (28) Operation timed out after 6000 milliseconds with 0 bytes
received

real 0m7.505s
user 0m0.000s
sys 0m0.000s

----------------------------------------------------------------------

Comment By: Rodric Glaser (rodricg)
Date: 2010-09-15 20:07

Message:
I will give it a try with the current git repo. Try adding a --max-time to
your curl command and make sure the connect doesn't actually timeout, just
gets delayed noticeably. (ie. delay-net.pl 1500 and --connect-timeout 4)
Once the connect has completed and the server does a sleep(100); you should
hit your max-time and timeout.

$ time curl -v --trace-time --connect-timeout 4 --max-time 6
http://127.0.0.1:82/
                                                             
18:08:37.593680 * About to connect() to 127.0.0.1 port 82 (#0)
18:08:37.593758 * Trying 127.0.0.1... connected
18:08:39.095568 * Connected to 127.0.0.1 (127.0.0.1) port 82 (#0)
18:08:39.095638 > GET / HTTP/1.1
18:08:39.095638 > User-Agent: curl/7.19.7 (x86_64-pc-linux-gnu)
libcurl/7.19.7 OpenSSL/0.9.8k zlib/1.2.3.3 libidn/1.15
18:08:39.095638 > Host: 127.0.0.1:82
18:08:39.095638 > Accept: */*
18:08:39.095638 >
18:08:45.100836 * Operation timed out after 6000 milliseconds with 0 bytes
received
18:08:45.100897 * Closing connection #0
curl: (28) Operation timed out after 6000 milliseconds with 0 bytes
received

real 0m7.512s
user 0m0.000s
sys 0m0.010s

----------------------------------------------------------------------

Comment By: Daniel Stenberg (bagder)
Date: 2010-09-14 23:56

Message:
I'm afraid I can't repeat your results. I did your initial iptables line
but changed to use dest port 8282 instead and here are the results from my
tests:

$ time ./src/curl --trace-time --connect-timeout 3 -v
localhost:8282/test/2
23:53:44.857027 * About to connect() to localhost port 8282 (#0)
23:53:44.857125 * Trying 127.0.0.1... Timeout
23:53:47.860091 * connect() timed out!
23:53:47.860130 * Closing connection #0
curl: (28) connect() timed out!

real 0m3.009s
user 0m0.004s
sys 0m0.000s

$ time ./src/curl --trace-time --connect-timeout 4 -v
localhost:8282/test/2
23:53:58.354201 * About to connect() to localhost port 8282 (#0)
23:53:58.354300 * Trying 127.0.0.1... Timeout
23:54:02.357410 * connect() timed out!
23:54:02.357450 * Closing connection #0
curl: (28) connect() timed out!

real 0m4.009s
user 0m0.000s
sys 0m0.004s

This is with the current git repo. Can you please retry your test with
that and see if you see the problem with this version?

----------------------------------------------------------------------

Comment By: Rodric Glaser (rodricg)
Date: 2010-09-08 22:48

Message:
np, my comment confused matters. I had curl_multi on my mind and I
completely overlooked the obvious solution to remove php from the mix...
just use curl :)

It appears that dns lookup time is also not included in the timeout.

Using the same setup (minus multi.php) and adding:
- a 127.0.0.1 DNS entry for loopback.han
- a dns lookup delay with: iptables -A OUTPUT -o eth0 -p udp --dport 53 -m
string --algo bm --string 'loopback' -j QUEUE

and then using the hostname:

# date ; time /opt/usr/bin/curl -v --trace-time --connect-timeout 4
--max-time 5 http://loopback.han:82/
Wed Sep 8 13:28:26 PDT 2010
13:28:27.759020 * About to connect() to loopback.han port 82 (#0)
13:28:27.759097 * Trying 127.0.0.1... connected
13:28:29.260180 * Connected to loopback.han (127.0.0.1) port 82 (#0)
13:28:29.260250 > GET / HTTP/1.1
13:28:29.260250 > User-Agent: curl/7.21.1 (x86_64-unknown-linux-gnu)
libcurl/7.21.1 OpenSSL/0.9.8m zlib/1.2.5 libidn/1.18 libssh2/1.2.2
13:28:29.260250 > Host: loopback.han:82
13:28:29.260250 > Accept: */*
13:28:29.260250 >
13:28:34.261411 * Operation timed out after 5001 milliseconds with 0 bytes
received
13:28:34.261451 * Closing connection #0
curl: (28) Operation timed out after 5001 milliseconds with 0 bytes
received

real 0m8.008s
user 0m0.000s
sys 0m0.003s

My primary goal was a reliable way to test overall connection timeouts
(for multiple pieces of software) ie. I'm not anxiously awaiting a fix ;)
However, I do use curl all the time and find it invaluable Thanks for all
your hard work!

----------------------------------------------------------------------

Comment By: Daniel Stenberg (bagder)
Date: 2010-09-08 09:35

Message:
man if I could just read the description properly I would've realized that
you indeed added time to the connection phase, sorry, but I'll stop
spamming this with stupid comments now and instead try to find some time to
work on this issue. I'll get back in a day or two I hope.

----------------------------------------------------------------------

Comment By: Daniel Stenberg (bagder)
Date: 2010-09-08 09:32

Message:
I've updated the summary since this clearly is not the connect time you see
added. Connecting to localhost is done in milliseconds.

----------------------------------------------------------------------

Comment By: Rodric Glaser (rodricg)
Date: 2010-09-08 00:49

Message:
Silly me, its much easier to use:

time curl http://127.0.0.1:82/ --connect-timeout 3 --max-time 4
curl: (28) Operation timed out after 4000 milliseconds with 0 bytes
received

real 0m5.511s
user 0m0.000s
sys 0m0.010s

----------------------------------------------------------------------

You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=100976&aid=3061535&group_id=976
Received on 2010-09-17