Re: CLOSESOCKETFUNCTION not always called in multi

From: Malcolm Matalka via curl-library <curl-library_at_lists.haxx.se>
Date: Mon, 27 Jan 2025 11:51:08 +0100

Malcolm Matalka <malcolm_at_terrateam.io> writes:

> Hello, I'm debugging a bug in my program using the multi interface. I'm still trying to work out some details but I thought maybe someone who knows the codebase better than I might just see it as obvious.
>
> In my case, I am setting SOCKETFUNCTION, TIMERFUNCTION, and CLOSESOCKETFUNCTION
> because I need to manage the sockets myself (I'm integrating curl against a
> concurrency library in Ocaml). Because of how the concurrency library works,
> instead of doing any work in those callbacks functions, I'm adding the event to
> a queue then processing the events after a "perform" or "action" call.
>
> What I'm seeing is that I have a POLL_REMOVE call for a socket, but then my CLOSESOCKETFUNCTION callback is not being called. I can see in the ktrace logs that the socket is directly being closed with "close".
>
> I *think* this is happening due libcurl deciding the connection has timed out and some logic chooses not to execute the close callback. But I'm not entirely sure.
>
> Any idea how I can turn on the tracing for cf-socket.c? I have set the global trace to 'all' but I am not seeing the logs I am looking for?
>
> I am on FreeBSD use curl 8.11.1.
>
> Thank you
>
> /Malcolm

After learning some lldb, this is what I got. Here is the log from my application (I log on timerfunction, socketfunction, and closefunction). Lines starting with '#' are my annotations to expalin


# We receive timeout for 1 ms
timeout_function : 1
still_running : 1

firing timeout
timeout
# We receive sockketfunction call for poll_in on fd 5. This adds the event to our queue
socket_function : poll_in : 5
# Setup new timeout
timeout_function : 2
# execute a perform
perform
still_running : 1

# This is the queue handler processing the queue
socket : poll_in : 5
# Async wait on 5
wait fd : 5

# we've timed out
firing timeout
timeout
timeout_function : 1
perform
still_running : 1

firing timeout
timeout

# update timeout
timeout_function : 8
perform
timeout_function : 8
still_running : 1

# Fire timeout
firing timeout
timeout

# We see now poll_remove for fd 5, this adds handling the poll_remove to the queue
socket_function : poll_remove : 5

Now, I would expect to see a "close_function" message here as we get a close, however we do not. I added a breakpoint in lldb to print the backgroud out on any call to close and I can see that libcurl is calling close right after the poll_remove.

  * frame #0: 0x00000008257d23c8 libc.so.7`close(fd=5) at close.c:43:10
    frame #1: 0x00000008231fda0a libcurl.so.4`destroy_async_data(async=0x00001c8252225620) at asyn-thread.c:433:5
    frame #2: 0x00000008231fdbca libcurl.so.4`Curl_resolver_is_resolved(data=0x00001c8252224800, entry=0x0000000820e163f8) at asyn-thread.c:612:5
    frame #3: 0x0000000823229205 libcurl.so.4`Curl_resolv_check(data=0x00001c8252224800, dns=0x0000000820e163f8) at hostip.c:1409:12
    frame #4: 0x000000082324be96 libcurl.so.4`multi_runsingle [inlined] state_resolving(multi=0x00001c82521e5000, data=0x00001c8252224800, stream_errorp=0x0000000820e163eb, resultp=0x0000000820e163f0) at
multi.c:2502:14
    frame #5: 0x000000082324be8a libcurl.so.4`multi_runsingle(multi=0x00001c82521e5000, nowp=0x0000000820e164f8, data=0x00001c8252224800) at multi.c:2681:12
    frame #6: 0x000000082324f3f8 libcurl.so.4`multi_run_expired(mrc=0x0000000820e164f0) at multi.c:3510:14
    frame #7: 0x000000082324d9f2 libcurl.so.4`multi_socket(multi=0x00001c82521e5000, checkall=<unavailable>, s=<unavailable>, ev_bitmask=<unavailable>, running_handles=0x0000000820e16604) at multi.c:3601:
12
    frame #8: 0x000000082324db6c libcurl.so.4`curl_multi_socket_action(m=<unavailable>, s=<unavailable>, ev_bitmask=<unavailable>, running_handles=<unavailable>) at multi.c:3727:10 [artificial]
    frame #9: 0x0000000000424af0 abb_curl_cli.native`caml_curl_multi_socket_action(v_multi=35172246200, v_fd=1, v_kind=1) at curl-helper.c:4981:10

Also, I do feel confident that the CLOSEFUNCTION behaviour does work because I see it working in other contexts.

If I understand what is happening here correctly, I believe this block of code should not call "wakeup_close" (which is defined as "close" in my environment) but instead should check if the close callback is defined and call that instead.

https://github.com/curl/curl/blob/curl-8_11_1/lib/asyn-thread.c#L426-L431

Is that correct?

Thank you

-- 
  Malcolm Matalka
  Terrateam
-- 
Unsubscribe: https://lists.haxx.se/mailman/listinfo/curl-library
Etiquette:   https://curl.se/mail/etiquette.html

Received on 2025-01-27