cURL / Mailing Lists / curl-library / Single Mail

curl-library

Re: Bug: curl 7.18.2/7.19.2 looses timeouts

From: <koettermarkus_at_gmx.de>
Date: Sun, 23 Nov 2008 03:49:48 +0100

Hi,

Daniel Stenberg wrote:
> On Thu, 20 Nov 2008, koettermarkus_at_gmx.de wrote:
>
>> I had the same idea first, but figured out I might be wrong, as the
>> timer_cb gets called, and following the code path I figured when calling
>
>> curl_multi_socket_action( ... TIMEOUT ... )
>> Curl_readwrite() gets called.
>
> Why would Curl_readwrite() get called on a timeout? I can only see that
> happen when the easy handle is in the PERFORM state.

For both cases the easy handle is in perform state:

..
* STATE: DO => DO_DONE handle 0x1fb3208; (connection #0)
sock_cb e 0x1faa658 s 9 what 1 cbp 0x7fff7e136430 sockp 0x1fb4ce0
socket callback: s=9 e=0x1faa658 what=IN Changing action from OUT to IN
setsock
* STATE: DO_DONE => WAITPERFORM handle 0x1fb3208; (connection #0)
* Conn 0 recv pipe 1 inuse 0 athead 1
* STATE: WAITPERFORM => PERFORM handle 0x1fb3208; (connection #0)
..

And the timer_cb calls Curl_readwrite

#0 0x0000000000401b53 in prog_cb ()
#1 0x00007fe9c14b29f5 in Curl_pgrsUpdate (conn=0x1c685b8) at progress.c:343
#2 0x00007fe9c14e1380 in Curl_readwrite (conn=0x1c685b8,
done=0x7fffc993148b) at transfer.c:1661
#3 0x00007fe9c14e8f7e in multi_runsingle (multi=0x1c3c988,
easy=0x1c68208) at multi.c:1279
#4 0x00007fe9c14e9dea in multi_socket (multi=0x1c3c988, checkall=false,
s=-1, ev_bitmask=0, running_handles=0x7fffc9931c94) at multi.c:1826
#5 0x00007fe9c14ea34b in curl_multi_socket_action
(multi_handle=0x1c3c988, s=-1, ev_bitmask=0,
running_handles=0x7fffc9931c94) at multi.c:1916
#6 0x00000000004017e6 in timer_cb ()
#7 0x0000000000401489 in multi_timer_cb ()
#8 0x00007fe9c14ea630 in update_timer (multi=0x1c3c988) at multi.c:1992
#9 0x00007fe9c14e7d6b in curl_multi_add_handle (multi_handle=0x1c3c988,
easy_handle=0x1c5f658) at multi.c:551
#10 0x0000000000401dee in new_conn ()
#11 0x0000000000401ee0 in fifo_cb ()
#12 0x00007fe9c129cd57 in ev_loop () from /usr/lib/libev.so.3
#13 0x00000000004021f5 in main ()

Curl_speedcheck might be called too:

#0 Curl_speedcheck (data=0x167efa8, now={tv_sec = 1227407782, tv_usec =
293315}) at speedcheck.c:43
#1 0x00007fafac26f3a2 in Curl_readwrite (conn=0x1687ec8,
done=0x7fffb46bd21b) at transfer.c:1664
#2 0x00007fafac276f7e in multi_runsingle (multi=0x1651858,
easy=0x1687b18) at multi.c:1279
#3 0x00007fafac277dea in multi_socket (multi=0x1651858, checkall=false,
s=-1, ev_bitmask=0, running_handles=0x7fffb46bda24) at multi.c:1826
#4 0x00007fafac27834b in curl_multi_socket_action
(multi_handle=0x1651858, s=-1, ev_bitmask=0,
running_handles=0x7fffb46bda24) at multi.c:1916
#5 0x00000000004017e6 in timer_cb ()

>> Curl_readwrite() would call Curl_speecheck().
>
> Yes, so if you call libcurl when the handle is in PERFORM it'll work in
> the sense that it'll run Curl_speecheck(). But of course the handle may
> not be in that state and Curl_speecheck() doesn't set any timeout or
> anything so you'll probably end up with no timeout set on the handle
> even if the speed should get checked soon again to see if it would match
> the criterias then.

beeing in PERFORM does not guarantee anything.

-------- working -------------
./evhiperfifo
Creating named pipe "hiper.fifo"
Now, pipe some URL's into > hiper.fifo
Adding easy 0x251b5b8 to multi 0x24f8858 (http://localhost:9000)
multi_timer_cb 0
timer_cb w 0x7fff0da8bde8 revents 0
* STATE: INIT => CONNECT handle 0x2524168; (connection #-5000)
* About to connect() to localhost port 9000 (#0)
* Trying 127.0.0.1... * connected
* Connected to localhost (127.0.0.1) port 9000 (#0)
* STATE: CONNECT => DO handle 0x2524168; (connection #0)
sock_cb e 0x251b5b8 s 6 what 2 cbp 0x7fff0da8bdb0 sockp (nil)
socket callback: s=6 e=0x251b5b8 what=OUT Adding data: OUT
setsock
> GET / HTTP/1.1
Host: localhost:9000
Accept: */*

* STATE: DO => DO_DONE handle 0x2524168; (connection #0)
sock_cb e 0x251b5b8 s 6 what 1 cbp 0x7fff0da8bdb0 sockp 0x2525c40
socket callback: s=6 e=0x251b5b8 what=IN Changing action from OUT to IN
setsock
* STATE: DO_DONE => WAITPERFORM handle 0x2524168; (connection #0)
* Conn 0 recv pipe 1 inuse 0 athead 1
* STATE: WAITPERFORM => PERFORM handle 0x2524168; (connection #0)
Progress: http://localhost:9000 (0/0)
multi_timer_cb 3000
check_run_count prev 0 still 1
check_run_count prev 1 still 1
timer_cb w 0x7fff0da8bde8 revents 256
Progress: http://localhost:9000 (0/0)
multi_timer_cb 3000
check_run_count prev 1 still 1
timer_cb w 0x7fff0da8bde8 revents 256
Progress: http://localhost:9000 (0/0)
* Operation too slow. Less than 10 bytes/sec transfered the last 3 seconds
Progress: http://localhost:9000 (0/0)
* Closing connection #0
* STATE: PERFORM => COMPLETED handle 0x2524168; (connection #-5000)
sock_cb e 0x251b5b8 s 6 what 4 cbp 0x7fff0da8bdb0 sockp 0x2525c40
socket callback: s=6 e=0x251b5b8 what=REMOVE
remsock
check_run_count prev 1 still 0
REMAINING: 0
DONE: http://localhost:9000 => (28) Operation too slow. Less than 10
bytes/sec transfered the last 3 seconds
--------------------

-------- not working ------------
  ./evhiperfifo
Creating named pipe "hiper.fifo"
Now, pipe some URL's into > hiper.fifo
Adding easy 0xe365b8 to multi 0xe13858 (http://localhost:9000)
multi_timer_cb 0
timer_cb w 0x7ffff2cc9028 revents 0
* STATE: INIT => CONNECT handle 0xe3f168; (connection #-5000)
* About to connect() to localhost port 9000 (#0)
* Trying 127.0.0.1... * connected
* Connected to localhost (127.0.0.1) port 9000 (#0)
* STATE: CONNECT => DO handle 0xe3f168; (connection #0)
sock_cb e 0xe365b8 s 6 what 2 cbp 0x7ffff2cc8ff0 sockp (nil)
socket callback: s=6 e=0xe365b8 what=OUT Adding data: OUT
setsock
> GET / HTTP/1.1
Host: localhost:9000
Accept: */*

* STATE: DO => DO_DONE handle 0xe3f168; (connection #0)
sock_cb e 0xe365b8 s 6 what 1 cbp 0x7ffff2cc8ff0 sockp 0xe40c40
socket callback: s=6 e=0xe365b8 what=IN Changing action from OUT to IN
setsock
* STATE: DO_DONE => WAITPERFORM handle 0xe3f168; (connection #0)
* Conn 0 recv pipe 1 inuse 0 athead 1
* STATE: WAITPERFORM => PERFORM handle 0xe3f168; (connection #0)
Progress: http://localhost:9000 (0/0)
multi_timer_cb 3000
check_run_count prev 0 still 1
check_run_count prev 1 still 1
timer_cb w 0x7ffff2cc9028 revents 256
Progress: http://localhost:9000 (0/0)
multi_timer_cb 3004
check_run_count prev 1 still 1
timer_cb w 0x7ffff2cc9028 revents 256
check_run_count prev 1 still 1
-------------

In general, we have
  * the first timeout when adding the easy handle (direct call as
timeout is 0)
  * the second timeout gets installed with 3000ms
  * in working cases the second timeout installs the third timeout with
~3000ms.
  * in non-working cases the second timeout does not call prog_cb.

>> The code for "evhiperfifo.c" is attached,
> Nice! I'll give it a check and I'll commit it in the examples section as
> I'm sure others will enjoy it as well.

If you need something for curl_multi_socket_action, I could throw in
something better.

MfG
Markus
Received on 2008-11-23