curl_multi_timeout: change in behavior after 8.16.0+

[jamacku]

I did this

Since curl-8.16.0~rc3, we saw a failing test suite for ruby-ethon (libcurl wrapper) - typhoeus/ethon#269

It seems that the issue might be caused by the introduction of dirty bit logic by:

• multi: add dirty bitset #17662
  More specifically, by commit: 6080143

Before 8.16.0, the return value contained two values [0, -1]. However, with the libcurl curl-8.16.0~rc3, there is just one entry [0]. Probably because -1 is now represented internally by the dirty bit.

I expected the following

Is this change in behavior expected? Thank you.

curl/libcurl version

curl 8.16.0+

operating system

Fedora Linux 44

[icing]

-1 is the value indicating that the timer needs to be cleared. This should always come when a timer was set, event set to a value of 0. So, if you see a 0 not followed by a -1 that looks wrong. But I do not know what your test code is really doing.

Are you able to get curl trace output on such runs? CURLOPT_DEBUGFUNCTION and setting curl_global_trace("all") to see timer handling....

[jamacku]

Thank you, @icing, for your prompt response. Here are the logs from the Ethon testsuite.

With curl 8.15.0:

#timerfunction callbacks
=== Enabling curl_global_trace('all') ===
=== About to call multi.add(easy) ===
[x-x] [MULTI] multi_timeout() says this has expired
=== TIMERFUNCTION CALLBACK: timeout_ms=0 (caller: /home/jamacku/Source/forks/ethon/lib/ethon/multi/stack.rb:29:in 'Ethon::Curl.multi_add_handle' <- /home/jamacku/Source/forks/ethon/lib/ethon/multi/stack.rb:29:in 'Ethon::Multi::Stack#add' <- /home/jamacku/Source/forks/ethon/spec/ethon/multi/options_spec.rb:111:in 'block (4 levels) in <top (required)>') ===
[0-x] [MULTI] [INIT] added to multi, mid=1, running=1, total=2
=== DEBUG: calls after add: [0] ===
=== About to call multi.delete(easy) ===
[0-x] [MULTI] [INIT] Expire cleared
=== TIMERFUNCTION CALLBACK: timeout_ms=-1 (caller: /home/jamacku/Source/forks/ethon/lib/ethon/multi/stack.rb:43:in 'Ethon::Curl.multi_remove_handle' <- /home/jamacku/Source/forks/ethon/lib/ethon/multi/stack.rb:43:in 'Ethon::Multi::Stack#delete' <- /home/jamacku/Source/forks/ethon/spec/ethon/multi/options_spec.rb:121:in 'block (4 levels) in <top (required)>') ===
[0-x] [MULTI] [COMPLETED] removed from multi, mid=1, running=0, total=1
=== DEBUG: calls after delete: [0, -1] ===
=== Expected -1 to cancel timer, got: -1 ===

Previously, the test also included calling curl_multi_socket_action() before calling curl_multi_remove_handle(), which was later removed.

#timerfunction callbacks
=== Enabling curl_global_trace('all') ===
=== About to call multi.add(easy) ===
[x-x] [MULTI] multi_timeout() says this has expired
=== TIMERFUNCTION CALLBACK: timeout_ms=0 (caller: /home/jamacku/Source/forks/ethon/lib/ethon/multi/stack.rb:29:in 'Ethon::Curl.multi_add_handle' <- /home/jamacku/Source/forks/ethon/lib/ethon/multi/stack.rb:29:in 'Ethon::Multi::Stack#add' <- /home/jamacku/Source/forks/ethon/spec/ethon/multi/options_spec.rb:111:in 'block (4 levels) in <top (required)>') ===
[0-x] [MULTI] [INIT] added to multi, mid=1, running=1, total=2
=== DEBUG: calls after add: [0] ===
=== About to call multi.socket_action ===
[0-x] [MULTI] [INIT] multi_run_dirty
[0-x] [MULTI] [INIT] -> [SETUP]
[0-x] [MULTI] [SETUP] -> [CONNECT]
[0-x] [READ] client_reset, clear readers
[0-0] [MULTI] [CONNECT] [CPOOL] added connection 0. The cache now contains 1 members
[0-0] Host localhost:3001 was resolved.
[0-0] IPv6: ::1
[0-0] IPv4: 127.0.0.1
[0-0] [SETUP] added
[0-0] [MULTI] [CONNECT] -> [CONNECTING]
[0-0] [HAPPY-EYEBALLS] created ipv6 (timeout 300000ms)
[0-0] [HAPPY-EYEBALLS] created ipv4 (timeout 300000ms)
[0-0] [MULTI] [CONNECTING] set expire[6] in 200000ns
[0-0] [HAPPY-EYEBALLS] ipv6 starting (timeout=300000ms)
[0-0]   Trying [::1]:3001...
[0-0] [TCP] cf_socket_open() -> 0, fd=106
[0-0] [TCP] local address ::1 port 37686...
[0-0] [HAPPY-EYEBALLS] ipv6 connect -> 0, connected=0
[0-0] [SETUP] Curl_conn_connect(block=0) -> 0, done=0
=== TIMERFUNCTION CALLBACK: timeout_ms=200 (caller: /home/jamacku/Source/forks/ethon/lib/ethon/multi/operations.rb:99:in 'Ethon::Curl.multi_socket_action' <- /home/jamacku/Source/forks/ethon/lib/ethon/multi/operations.rb:99:in 'Ethon::Multi::Operations#socket_action' <- /home/jamacku/Source/forks/ethon/spec/ethon/multi/options_spec.rb:117:in 'block (4 levels) in <top (required)>') ===
=== DEBUG: calls after socket_action: [0, 200] ===
=== About to call multi.delete(easy) ===
[0-0] [MULTI] [CONNECTING] multi_done: status: 0 prem: 1 done: 0
[0-0] [WRITE] [OUT] done
[0-0] [READ] client_reset, clear readers
[0-x] [MULTI] [CONNECTING] multi_done_locked, in use=0
[0-0] [MULTI] [CONNECTING] multi_done, not reusing connection=0, forbid=0, close=0, premature=1, conn_multiplex=0
[0-0] closing connection #0
[0-0] [MULTI] [CONNECTING] Expire cleared
=== TIMERFUNCTION CALLBACK: timeout_ms=-1 (caller: /home/jamacku/Source/forks/ethon/lib/ethon/multi/stack.rb:43:in 'Ethon::Curl.multi_remove_handle' <- /home/jamacku/Source/forks/ethon/lib/ethon/multi/stack.rb:43:in 'Ethon::Multi::Stack#delete' <- /home/jamacku/Source/forks/ethon/spec/ethon/multi/options_spec.rb:121:in 'block (4 levels) in <top (required)>') ===
[0-0] [MULTI] [COMPLETED] removed from multi, mid=1, running=0, total=1
=== DEBUG: calls after delete: [0, 200, -1] ===
=== Expected -1 to cancel timer, got: -1 ===

With curl 8.18.0 there is a missing -1:

#timerfunction callbacks
=== Enabling curl_global_trace('all') ===
=== About to call multi.add(easy) ===
=== TIMERFUNCTION CALLBACK: timeout_ms=0 (caller: /home/jamacku/ethon/lib/ethon/multi/stack.rb:29:in 'Ethon::Curl.multi_add_handle' <- /home/jamacku/ethon/lib/ethon/multi/stack.rb:29:in 'Ethon::Multi::Stack#add' <- /home/jamacku/ethon/spec/ethon/multi/options_spec.rb:111:in 'block (4 levels) in <top (required)>') ===
[0-x] [MULTI] [INIT] added to multi, mid=1, running=1, total=2
=== DEBUG: calls after add: [0] ===
=== About to call multi.delete(easy) ===
[0-x] [MULTI] [COMPLETED] removed from multi, mid=1, running=0, total=1
=== DEBUG: calls after delete: [0] ===
=== Expected -1 to cancel timer, got: 0 ===

Calling additional action before curl_multi_remove_handle() makes -1 appear again.

 #timerfunction callbacks
=== Enabling curl_global_trace('all') ===
=== About to call multi.add(easy) ===
=== TIMERFUNCTION CALLBACK: timeout_ms=0 (caller: /home/jamacku/ethon/lib/ethon/multi/stack.rb:29:in 'Ethon::Curl.multi_add_handle' <- /home/jamacku/ethon/lib/ethon/multi/stack.rb:29:in 'Ethon::Multi::Stack#add' <- /home/jamacku/ethon/spec/ethon/multi/options_spec.rb:111:in 'block (4 levels) in <top (required)>') ===
[0-x] [MULTI] [INIT] added to multi, mid=1, running=1, total=2
=== DEBUG: calls after add: [0] ===
=== About to call multi.socket_action ===
[0-x] [MULTI] [INIT] multi_run_dirty
[0-x] [MULTI] [INIT] -> [SETUP]
[0-x] [MULTI] [SETUP] -> [CONNECT]
[0-x] [READ] client_reset, clear readers
[0-0] [MULTI] [CONNECT] [CPOOL] added connection 0. The cache now contains 1 members
[0-0] Host localhost:3001 was resolved.
[0-0] IPv6: ::1
[0-0] IPv4: 127.0.0.1
[0-0] [SETUP] added
[0-0] [MULTI] [CONNECT] -> [CONNECTING]
[0-0] [HAPPY-EYEBALLS] init ip ballers for transport 3
[0-0] [HAPPY-EYEBALLS] starting first attempt for ipv6 -> 0
[0-0]   Trying [::1]:3001...
[0-0] [TCP] cf_socket_open() -> 0, fd=88
[0-0] [TCP] local address ::1 port 60628...
[0-0] [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
[0-0] [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 200ms
[0-0] [TIMER] [HAPPY_EYEBALLS] set for 200000ns
[0-0] [SETUP] Curl_conn_connect(block=0) -> 0, done=0
[0-0] [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 200ms
=== TIMERFUNCTION CALLBACK: timeout_ms=200 (caller: /home/jamacku/ethon/lib/ethon/multi/operations.rb:99:in 'Ethon::Curl.multi_socket_action' <- /home/jamacku/ethon/lib/ethon/multi/operations.rb:99:in 'Ethon::Multi::Operations#socket_action' <- /home/jamacku/ethon/spec/ethon/multi/options_spec.rb:117:in 'block (4 levels) in <top (required)>') ===
=== DEBUG: calls after socket_action: [0, 200] ===
=== About to call multi.delete(easy) ===
[0-0] [MULTI] [CONNECTING] multi_done: status: 0 prem: 1 done: 0
[0-0] [WRITE] [OUT] done
[0-0] [READ] client_reset, clear readers
[0-x] [MULTI] [CONNECTING] multi_done_locked, in use=0
[0-0] [MULTI] [CONNECTING] multi_done, terminating conn #0 to localhost:3001, forbid=0, close=0, premature=1, conn_multiplex=0
[0-0] closing connection #0
[0-0] [MULTI] [CONNECTING] [TIMEOUT] all cleared
=== TIMERFUNCTION CALLBACK: timeout_ms=-1 (caller: /home/jamacku/ethon/lib/ethon/multi/stack.rb:43:in 'Ethon::Curl.multi_remove_handle' <- /home/jamacku/ethon/lib/ethon/multi/stack.rb:43:in 'Ethon::Multi::Stack#delete' <- /home/jamacku/ethon/spec/ethon/multi/options_spec.rb:121:in 'block (4 levels) in <top (required)>') ===
[0-0] [MULTI] [COMPLETED] removed from multi, mid=1, running=0, total=1
=== DEBUG: calls after delete: [0, 200, -1] ===
=== Expected -1 to cancel timer, got: -1 ===

[icing]

Thanks! That made it clear to me what was happening. Please check #20502 which should restore the old, correct behaviour.

[jamacku]

@icing Thank you for the prompt fix. I have verified that your patch fixes the issue (test now passes).

[jay]

Thanks