Re: CLOSESOCKETFUNCTION not always called in multi

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

Malcolm Matalka <malcolm_at_terrateam.io> writes:

> 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?

Sorry to spam, but I think my understanding is not entirely correct. I believe this is a socket that curl (or the multi interface in particular?) is using for its own needs, and it's not necessarily part of a handle. The opensocket and closesocket callbacks are for a handle, which means they do not get called in this case.

The issue with my usage is that despite opensocket and closesocket not being called, the socketfunction callback is called to manage polling, however due to some constraints on my system, I cannot actually do the socketfunction callback work in the callback, but I think curl assumes it can, in which case it believes its safe to call close on the socket after the POLL_REMOVE.

The reason I can using CLOSESOCKET in a handle is because I need to be back in my program's control flow to do some cleanup before actually closing the socket.

Is my understanding correct? I understand this might be an unexpected usage of libcurl, but are there any suggested workarounds?


>
> 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