[BUG] Complete a curl operation that is never scheduled - #4395
Conversation
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #4395 +/- ##
==========================================
+ Coverage 82.61% 82.67% +0.06%
==========================================
Files 511 511
Lines 20132 20172 +40
==========================================
+ Hits 16631 16675 +44
+ Misses 3501 3497 -4
🚀 New features to boost your workflow:
|
|
Two things on this page that a reviewer would otherwise have to dig for. The two red jobs are both #4265
That is #4265, which @dbarker opened on 17 July and @yogarajalakshmi-s is on. This change does touch session teardown, so I did not want to leave it at "known flake". Same case, same build configuration, 25 runs on
The assertion is a 20 ms wall clock budget, so an idle box gives 0 and a loaded runner gives 247. Nothing here moves it. Where the 11 uncovered lines areBuilding the coverage configuration locally reproduces Codecov's 8 and 3 exactly. They are three different things: Three are not new. The Five are the Three are the |
4ec7974 to
73f5f82
Compare
8e76621 to
b3d9965
Compare
| async_data_->session = session; | ||
| async_data_->callback = std::move(callback); | ||
|
|
||
| DispatchEvent(opentelemetry::ext::http::client::SessionState::Connecting); |
There was a problem hiding this comment.
Thanks, the callback publication reads correct now.
One more concern on this line, from the same window: if the client already has an IO thread, a handler can call CancelSession() from Connecting, and Cleanup() can dispatch Cancelled on the IO thread before this Connecting callback returns. That also makes both DispatchEvent() calls write session_state_ concurrently.
The current test uses a new client, so the background thread starts only after SendAsync() returns and does not cover this interleaving. Could we serialize cleanup with the initial event dispatch and add a test that starts the IO thread before cancelling from Connecting?
There was a problem hiding this comment.
Measured it, and both halves hold.
The interleaving happens. On a client that has already completed one request, a handler cancelling from Connecting is still inside OnEvent when the IO thread runs Cleanup() and dispatches its own Cancelled. I held the handler open and counted threads inside it: two, five runs out of five. Drop the warming request and it is one, which is what every case in the file does today.
The stores race. ThreadSanitizer on that scenario, on this branch before the change, five runs out of five:
Write of size 1 by main thread:
#0 HttpOperation::DispatchEvent(...) http_operation_curl.cc:415
#1 HttpOperation::SendAsync(...) http_operation_curl.cc:1466
#2 Session::SendRequest(...) http_client_curl.cc:209
Previous write of size 1 by thread T2:
#0 HttpOperation::DispatchEvent(...) http_operation_curl.cc:415
#1 HttpOperation::Cleanup() http_operation_curl.cc:536
#2 Session::FinishOperation() http_client_curl.cc:269
#3 HttpClient::doAbortSessions() http_client_curl.cc:808
Past the undefined behavior the later store wins, so GetSessionState() finished at Connecting for an operation that had been cancelled.
What changed. DispatchEvent stores before it calls the handler, and session_state_ is now a std::atomic. Storing first is what fixes the value: the store is then ordered ahead of the cancel, which goes through sessions_m_ and session_ids_m_, and the IO thread takes session_ids_m_ before it can reach Cleanup(). The atomic covers the paths with no such handoff, where a third thread cancels rather than the handler. SessionState is a std::uint8_t enum and std::atomic of it is one byte with alignment one and lock free, so the layout of the installed type does not move.
I went through the other readers before moving the store. Nothing reads GetSessionState() from inside its own event, and every internal reader, ~HttpOperation, Cleanup, the progress and debug callbacks, and PerformCurlMessage, reads it after a dispatch has already returned, where both orders give the same value. The two synchronous Get and Post paths run on one thread with no handler at all.
The test. CancelFromConnectingWhilePollingCompletes warms the client, cancels from Connecting, and stays in the handler until the IO thread has entered it too, so the overlap is deterministic rather than lucky. Without the change it reports the race five runs out of five, with it none, and the whole file is clean under ThreadSanitizer. It is also the only thing in this file that reaches the is_cleaned_ recheck at the end of SendAsync, which closes the coverage gap I flagged on the Codecov comment. I instrumented both tail branches and ran the whole binary: the recheck was entered exactly once, by this scenario, and the three cases already on the branch all took the other branch instead.
One detail worth knowing for anyone who touches it. My first version counted the overlap with acq_rel atomics and ThreadSanitizer went quiet. The IO thread's release and the caller's later read-modify-write on the same counter synchronize with each other, which orders the two state stores and hides exactly what the case exists to catch. The counters are relaxed now. I confirmed that with a deliberate unsynchronized counter on the same line as a control: the acq_rel build reported neither it nor the real race, the relaxed build reported both.
I had opened #4408 for this before deciding to fix it here, since it reproduces on main independently of this change. This branch closes it, and I have corrected the claim there that the member could not be made atomic without moving the layout.
There was a problem hiding this comment.
One correction to what I wrote above, because I stated it more broadly than it holds.
I said every internal reader takes GetSessionState() after a dispatch has already returned. There is one that does not have to. ~HttpOperation switches on it to decide whether to wait on the future, and a handler that destroys its own operation from inside an event, which is what Session::SendRequest does when a session is reused and is the shape of #4396, runs that switch while the dispatch is still in the handler. Its case list is Connecting, Connected, Sending, and it does not include Created, so storing first can change which side of it that path lands on.
I measured it rather than reason about it. Instrumenting the destructor to record every state it observes and running the same set of cases both ways:
store after the handler: Response 28 ConnectFailed 11 SendFailed 2 Created 2 Connecting 1
store before the handler: Response 29 ConnectFailed 11 SendFailed 1 Created 2 Connecting 1
The one that moves between SendFailed and Response is run to run variation in a suite that talks to a socket, not the ordering. So nothing the suite exercises changes, and the only path where the two could differ is a handler destroying its own operation, which is a use after free today with or without this.
b3d9965 to
8a01384
Compare
|
Update on the eleven uncovered patch lines I wrote about earlier, now that the polling client case is on the branch. Measured with the same
The three were the Of the eight left, three are the The other five are the So reaching that branch needs the handle to be taken away and |
92b8bb5 to
efbb0f5
Compare
…_read Two corrections to the change before it, both found reviewing it rather than reported. The wait cannot be interrupted. wakeupBackgroundThread reaches the worker through the multi handle, and the whole point of that branch is that there is not one, so the destructor cannot cut the wait short and the previous commit saying teardown was unchanged is wrong. Destroying a client whose worker was inside the wait measured 168 ms, five runs out of five. Taking the same wait in 16 ms slices and rechecking is_shutdown_ leaves the retry rate where it was and brings that to 10 ms, five runs out of five. And curl_multi_info_read was still called with the handle libcurl had refused to give. curl_multi_poll and curl_multi_wait cannot see one, since they sit inside the branch that only runs when perform succeeded. curl_multi_add_handle and curl_multi_remove_handle can, but they are in doAddSessions and doRemoveSessions, which open-telemetry#4395 and open-telemetry#4405 rewrite, so they are named in the description rather than changed here. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
d545971 to
765f147
Compare
…_read Two corrections to the change before it, both found reviewing it rather than reported. The wait cannot be interrupted. wakeupBackgroundThread reaches the worker through the multi handle, and the whole point of that branch is that there is not one, so the destructor cannot cut the wait short and the previous commit saying teardown was unchanged is wrong. Destroying a client whose worker was inside the wait measured 168 ms, five runs out of five. Taking the same wait in 16 ms slices and rechecking is_shutdown_ leaves the retry rate where it was and brings that to 10 ms, five runs out of five. And curl_multi_info_read was still called with the handle libcurl had refused to give. curl_multi_poll and curl_multi_wait cannot see one, since they sit inside the branch that only runs when perform succeeded. curl_multi_add_handle and curl_multi_remove_handle can, but they are in doAddSessions and doRemoveSessions, which open-telemetry#4395 and open-telemetry#4405 rewrite, so they are named in the description rather than changed here. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
RepeatedCallerThreadCancelsAreClean summed Cancelled and Response over twenty attempts against a closed port and asked for at least one each. There is a third way such an attempt ends: the connection fails before the cancel arrives, and the cancel is then correctly a no-op. Where the caller and the IO thread share a core that is the usual outcome, and the case fails. Measured with the run pinned to one core, fifteen runs each: 15 of 15 fail on main at 3fb1d31, on open-telemetry#4395 at 66ab56c, and on this branch either side of the change it carries, all with the same 3 to 7 cancels out of 20. Unpinned all four pass. The failure the valgrind job hit is that, not anything about the handle accounting. The connection failure is counted apart from terminal_count_, which two other cases pin to an exact value, and it is taken before the existing chain rather than inside it, because ACancelBeforeTheResponseReportsCancelled cancels from ConnectFailed and needs that branch to keep firing. The case now asks each attempt to end somewhere the handler is told about rather than to end the same way twenty times, which is what it was after. Pinned to one core it goes from 15 of 15 failing to 0 of 15. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
66ab56c to
3bb5d7c
Compare
…_read Two corrections to the change before it, both found reviewing it rather than reported. The wait cannot be interrupted. wakeupBackgroundThread reaches the worker through the multi handle, and the whole point of that branch is that there is not one, so the destructor cannot cut the wait short and the previous commit saying teardown was unchanged is wrong. Destroying a client whose worker was inside the wait measured 168 ms, five runs out of five. Taking the same wait in 16 ms slices and rechecking is_shutdown_ leaves the retry rate where it was and brings that to 10 ms, five runs out of five. And curl_multi_info_read was still called with the handle libcurl had refused to give. curl_multi_poll and curl_multi_wait cannot see one, since they sit inside the branch that only runs when perform succeeded. curl_multi_add_handle and curl_multi_remove_handle can, but they are in doAddSessions and doRemoveSessions, which open-telemetry#4395 and open-telemetry#4405 rewrite, so they are named in the description rather than changed here. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
An operation could be given a promise and then never handed to the IO thread, which left the caller waiting on a future nobody was in a position to complete. FinishSession() blocked forever. Three ways in. SendAsync dispatched Connecting before it reset the operation flags and published the cancel route, so a handler that cancelled from that event had its cancel overwritten and the session removed from the client behind it. CreateSession hands back an unregistered session when the URL does not parse, and CURLOPT_URL is not checked when it is set, so Setup succeeds and the same dead end is reached with no handler involved. And doAddSessions dropped the result of curl_multi_add_handle, so a rejected handle left an operation nobody would ever run. The flags and the cancel route are published before the event now, and the future is published after it, so a handler calling FinishSession() from the event still returns rather than waiting on a transfer that has not been scheduled. ScheduleAddSession reports whether the session was still registered, and SendAsync finishes the operation itself when it was not, or when the event cancelled it. doAddSessions finishes the ones the multi handle rejects, and does it outside sessions_m_, since FinishOperation reaches the handler. The completion callback is published with them rather than after the event. Cleanup() takes is_cleaned_ at its start and swaps async_data_->callback about forty lines later, so the is_cleaned_ recheck only says cleanup has begun, not that it has finished reading the callback. A handler cancelling from Connecting wakes the IO thread, which can reach the swap first, find an empty callback, and never run the completion, which is also what clears is_session_active_. The two accesses to the std::function race as well. Found by @lalitb in review. The conditional include of global_log_handler.h goes too. The file already pulled it in under the else branch of ENABLE_OTLP_COMPRESSION_PREVIEW, and this change needs it unguarded, so with compression preview off both were live and include-what-you-use reported one too many. Fixes open-telemetry#4390. Fixes open-telemetry#4393. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
DispatchEvent stored session_state_ after the handler had returned. A handler that cancels from the first event of a client that is already polling lets the background thread finish the operation and dispatch a state of its own, so both threads wrote that member, and the store left until after the handler returned overwrote the cancel with a state the operation had left. Found by @lalitb in review. The store moves ahead of the handler and the member becomes atomic. SessionState is a uint8_t enum and std::atomic of it is one byte with alignment one, so the layout of an installed type does not move. The new case warms the client with a completed request first, because the background thread is only spawned after SendAsync returns and without one there is nothing for the event to overlap. It is the only case in this file that reaches the is_cleaned_ recheck at the end of SendAsync. Its counters are relaxed deliberately, since an acquire or a release on them gives the two threads an ordering the code under test does not have and the racing store stops being reported. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
The comments carried the reasoning that found the bug as well as the rule the code follows. The rule is what a reader needs; the rest belongs in the pull request. Each block now states its constraint and stops, and the two member comments in the installed headers follow the one line trailing form the file already uses next to them. No code changes. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
Four things from review. A session whose URL never parsed kept id 0. Pending removals are keyed by session id, and HttpCurlEasyResource's move assignment is a swap whose destructor frees nothing, so a second unparsable URL displaced the first handle into a temporary that nothing freed. Measured with LeakSanitizer: 5556 bytes in 5 allocations, an easy handle and four strings, 3 of 3. With an id, 0 bytes, 3 of 3. doAddSessions answered false when every add failed, although finishing the rejected sessions had just queued their removals. The loop's idle check runs doRemoveSessions before doAddSessions, so it could exit with that work still queued. It now reports the follow-up work. The failure was logged while sessions_m_ was held. The log handler is application code that can re-enter the client, so the rejection is collected under the lock and reported outside it, next to the finish that was already there for the same reason. A scheduling failure reached Cleanup as Cancelled, which is documented as a manual cancel, carrying a reason read from a curl result that is still CURLE_OK. It is now reported as a create failure that says what happened. The terminal assertions are exact rather than at least one. That matters: measured, cancelling once the transfer belongs to the IO thread produces two terminal events, which is open-telemetry#4360, and the old assertion absorbed it. The count is pinned so a change to it is visible. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
The branch added for a session the client never registered reported the failure and then finished the operation. The handler is replaceable, and one that calls FinishSession() from that event waits on a promise that only the Cleanup() below the dispatch can fulfil, on the same stack. Measured: the case hung for the whole 60 second bound, twice, exit 124. With the order reversed it returns in under a second, 3 of 3. The terminal state goes in before Cleanup() so it still reports one event rather than a manual cancel, and the report now happens after the operation is done, which is the order the exporters already follow: retire, then call anything replaceable. The case stays, because the failure mode is a hang. Nothing else in the file would notice the order being put back. 32 tests pass, 3 of 3. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
The case counted terminal events and stopped there, so an honoured cancel and a request that was never registered looked the same to it. They are not the same, and what this path reports today is the second one. Created is dispatched from the constructor, before curl_operation_ holds the operation, so a cancel from that event reaches the Session but not the operation. Scheduling then finds no registration and reports a failed create. The caller asked to cancel and is told the create failed. Measured: zero Cancelled, one CreateFailed. An earlier measurement on this branch saw the opposite, before the unregistered path was reordered to finish before it reports, so the classification moved with that change and nothing here was watching. Pinned as it is rather than as it should be. Making it a cancel means moving the first events out of the constructor, which is the startup ordering the issue is about rather than something to add on the side. Pinning it means the day it changes is visible. The comment above the counting handler also still described the old ordering, where the event reached the handler before the state was stored. It stores first now. 32 tests pass, 3 of 3. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
…serting it Two things this branch said but did not enforce. The cases here cover waits that are meant to end. When one stops ending it hangs rather than fails, and nothing bounded them, so a regression took the whole job with it instead of reporting. That happened three times while this branch was being written, each time as exit 124 with no case after it running. Every curl case now carries a CTest timeout of 120 seconds, read back from ctest --show-only=json-v1 as 120.0 on all 35. The slowest case that legitimately waits takes thirty. The description also claimed that std::atomic<SessionState> is one byte, aligned to one, and lock free, so the installed layout does not move. That was a measurement on one toolchain stated as a property of the language. The standard promises none of it. The size and alignment halves are now static_asserts, so a toolchain where they do not hold says so while building rather than silently changing an installed type. 32 tests pass. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
The case asserts that two callbacks are inside the handler at once, which is what this client does today. EventHandler does not say whether one request's callbacks can overlap, so a handler written against the interface is not obliged to be re-entrant, and an assertion that reads like a promise is the wrong thing to leave behind. The number stays, because reaching that overlap is the point of the case and a client that began serialising callbacks per operation should be noticed rather than absorbed. The comment now says which of the two it is. 32 tests pass. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
Startup handed the operation out in pieces. The Session route went out before the callback, and the promise was created after the first event, so a cancel arriving in between could reach an operation whose callback was still empty. Whoever noticed that cleanup had started could then publish the completion, which meant FinishSession could return while the IO thread was still inside a user handler. The route is now the last thing stored. Nothing else can bring the IO thread to this operation: Abort only raises a flag, and the abort queue is reached through that same route, so by the time the operation is reachable the callback, the promise and the future all exist. Cleanup is then the only thing that ever fulfils the promise, at its tail, after the terminal event and the completion callback have run, and the recheck that used to fulfil it from the caller is gone. A promise that exists before the first event would make a handler calling FinishSession from that event wait on itself, which is what the late future used to avoid. A thread local scope answers it directly: every user callback runs inside one, and Finish returns early when the calling thread is already inside a callback for this operation. It returns before the finished flag, so a caller outside the callback still gets to wait, which the flag used to swallow. Measured with a handler that holds inside the terminal event for 200 ms. Before, on the runs where the IO thread delivered that event, Finish returned in 0 ms with the handler still running. After, it waits 400 ms, the length of the two held events, and the handler is never still running when it returns: 6 runs of 6. The case that came out of that probe is on the branch, and its comment says what it does not prove. Which thread delivers the terminal event is not something it can choose, and on the caller-thread schedule there is nothing for Finish to wait for, so reverting this change leaves it green 10 times in 10. The evidence above is the before and after, not that case. 33 tests pass, 3 of 3. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
Of the three ways an operation ends up with nothing to run it, two told the handler CreateFailed and the third told it Cancelled. The enum documents that one as "(manually) cancelled", and both exporters print that word: the OTLP HTTP client logs "Session state: (manually) cancelled." and the Elasticsearch exporter logs "(manually) cancelled". So a handle libcurl refused to schedule reached the operator as a request somebody cancelled, and the reason libcurl gave for refusing it was not reported at all. Nothing behaves differently for it. Both states set need_stop in the OTLP handler and both end the wait in the Elasticsearch one, so what changes is the message, from a cancel that did not happen to a failed create carrying curl_multi_strerror. The ordering the registered path already used is now one method rather than three lines in two places: the state goes in ahead of the cleanup, which would otherwise report the cancel, and the cleanup goes in ahead of the event, so a handler calling FinishSession() from it is not waiting on the promise that cleanup is the only thing able to fulfil. That branch had no test. It has one now, and it needs no seam around libcurl: SendAsync does the whole async setup and Session::SendRequest is what starts the worker, so a case can build the operation, send it, put the client on a multi handle that refuses every add, and drive doAddSessions itself on one thread. Reverting the finish to the plain one it had before fails the case on both assertions. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
…es up The overlapping cancel case holds the calling thread inside the first event until the background thread has entered one of its own, so the two really do overlap. It waited on inside_events_, which is raised on the way into an event and lowered on the way out, and the event the background thread dispatches there is a few atomics long. Sampling that every millisecond almost never catches it at two, so the bound was spent in full on every run: 30005, 30509, 30006 and 30015 ms across four runs that all passed, because the count the assertion reads is written by the thread that creates the overlap and never goes down. Waiting on that count instead leaves as soon as the overlap has happened. The case goes from 30006 ms to 511 ms, ten runs out of ten, and the whole binary from about 53 seconds to 23.5. It also makes the case detect what it exists for. Against a faithful revert of what this branch changed about session_state_, a plain member again and the store back after the handler, ThreadSanitizer reports the race five runs out of five with the shorter wait and none at all with the longer one, which spends thirty seconds and a great many reads of that same address between the two writes. With the change in place it reports none either way. A bound that does expire now means the overlap really did not happen, so it is recorded and checked rather than left to be read as the client having dispatched one event. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
A probe left cstdio behind when its printf went, and the lambda handed to SendAsync needs functional. Both are what include-what-you-use asks for. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
resetMultiHandle keeps the sessions whose ids are already in pending_to_add_session_ids_ and takes the rest. A request that has not reached ScheduleAddSession yet is one of the rest: the caller is between CreateSession, which registered the session, and SendAsync, which is what queues the id. So the reset cancels a session whose operation is about to be given a promise, and on main the id then goes into the queue whatever became of the session, where doAddSessions finds nothing to add and moves on. The promise is never fulfilled and FinishSession never returns. This branch already refuses that id, and this is the case for it. Nothing is sent before the reset, so there is no IO thread and the caller stands exactly where the interleaving puts it, in program order rather than in a window. That also keeps it away from the multi handle: taking one from a running thread is not something libcurl allows, and a case that did it could not say whether what it saw was the client or itself. Against a faithful revert of what this branch changed about ScheduleAddSession, the id going in whatever became of the session, it hangs: three runs out of three reach the 90 second bound with no case finished. It passes in 503 ms with the change, three out of three. All 35 cases in the binary pass, in 24.5 seconds. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
The case reads CURLM, and curlver.h is not where that comes from. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
The copy inside the retry guard was there for the case that needs gmock. The one added at the top for include-what-you-use covers every build, so the guarded one is a duplicate, and the abiv2-preview job says so while abiv1 does not. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
…_read Two corrections to the change before it, both found reviewing it rather than reported. The wait cannot be interrupted. wakeupBackgroundThread reaches the worker through the multi handle, and the whole point of that branch is that there is not one, so the destructor cannot cut the wait short and the previous commit saying teardown was unchanged is wrong. Destroying a client whose worker was inside the wait measured 168 ms, five runs out of five. Taking the same wait in 16 ms slices and rechecking is_shutdown_ leaves the retry rate where it was and brings that to 10 ms, five runs out of five. And curl_multi_info_read was still called with the handle libcurl had refused to give. curl_multi_poll and curl_multi_wait cannot see one, since they sit inside the branch that only runs when perform succeeded. curl_multi_add_handle and curl_multi_remove_handle can, but they are in doAddSessions and doRemoveSessions, which open-telemetry#4395 and open-telemetry#4405 rewrite, so they are named in the description rather than changed here. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
071ddeb to
b2e9e22
Compare
RepeatedCallerThreadCancelsAreClean summed Cancelled and Response over twenty attempts against a closed port and asked for at least one each. There is a third way such an attempt ends: the connection fails before the cancel arrives, and the cancel is then correctly a no-op. Where the caller and the IO thread share a core that is the usual outcome, and the case fails. Measured with the run pinned to one core, fifteen runs each: 15 of 15 fail on main at 3fb1d31, on open-telemetry#4395 at 66ab56c, and on this branch either side of the change it carries, all with the same 3 to 7 cancels out of 20. Unpinned all four pass. The failure the valgrind job hit is that, not anything about the handle accounting. The connection failure is counted apart from terminal_count_, which two other cases pin to an exact value, and it is taken before the existing chain rather than inside it, because ACancelBeforeTheResponseReportsCancelled cancels from ConnectFailed and needs that branch to keep firing. The case now asks each attempt to end somewhere the handler is told about rather than to end the same way twenty times, which is what it was after. Pinned to one core it goes from 15 of 15 failing to 0 of 15. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
2 participants
Fixes #4390.
Fixes #4393.
Fixes #4408.
An operation could be given a promise and then never handed to the IO thread, and then nobody was in a position to complete it.
FinishSession()blocked forever.Three ways in, and each one hangs on
maintoday:CreatedorConnectingeventSendAsyncdispatched the event and only then resetis_aborted_, so the cancel was thrown away, whileCleanupSession()had already taken the session out of the client.ScheduleAddSessionthen erased the pending abort for good measureCreateSessionhands back a session it never registered and never gave an id.CURLOPT_URLis not checked when it is set, soSetup()succeeds and the request reachesScheduleAddSession(0), which nothing can findcurl_multi_add_handlerejects the handleThey are one invariant with three holes in it: an operation that never gets scheduled still has to finish.
What changed
The flags and the cancel route are published before the first event, so a handler cancelling from it is not overwritten by the rest of
SendAsync. The future is published after the event, deliberately: a handler callingFinishSession()fromConnectingwould otherwise wait on a transfer that has not been scheduled yet, withSendAsyncunable to schedule it because it is inside that handler.ScheduleAddSessionnow reports whether the session was still registered, andSendAsyncfinishes the operation itself when it was not, or when the event cancelled it.doAddSessionsdoes the same for the ones libcurl rejects, outsidesessions_m_, since finishing one reaches the caller's handler and a handler that cancels takes that lock again.All three say the same thing to the handler, a failed create carrying the reason, through one method rather than the same three lines in two places. The one libcurl refuses used to arrive as
Cancelled, which the enum calls "(manually) cancelled" and which both exporters print in those words, for a request nobody cancelled and without the reason libcurl gave. Nothing behaves differently for the change:CreateFailedandCancelledboth setneed_stopin the OTLP HTTP handler and both end the wait in the Elasticsearch one, so what moves is the message.There is one ordering subtlety worth pointing at. Between publishing the future and scheduling the add, the IO thread can already have torn the operation down and found no future to complete, so
SendAsyncrechecksis_cleaned_and settles it with anexchange. Whichever side gets there first, the value is set exactly once.That same window had a second defect in it, raised by @lalitb in review.
DispatchEventstoredsession_state_after the handler returned, so a handler cancelling from the first event on a client that is already polling had the IO thread storing aCancelledof its own at the same time, and the store after the handler returned overwrote it. ThreadSanitizer reports it on this branch before the change, five runs out of five. The store now happens before the handler runs, which orders it ahead of the cancel throughsessions_m_andsession_ids_m_, and the member is astd::atomicfor the paths where a third thread cancels instead of the handler.SessionStateis astd::uint8_tenum, and on the toolchains this was built withstd::atomicof it stays one byte with alignment one, so the layout does not move. The standard promises neither, so both arestatic_asserts next to the member rather than a claim here: a toolchain where they do not hold fails the build instead of changing the layout quietly. Worth being exact about whose layout, since I was not.ext/CMakeLists.txtinstalls four headers fromext/http/clientandhttp_operation_curl.his not one of them, so a CMake consumer never sees this type.//exttakeshdrs = glob(["include/**/*.h"]), so a Bazel consumer does, which is why the guard is worth keeping rather than dropping. Lock freedom is a separate property and nothing here checks it, sinceis_always_lock_freeis C++17 and this still builds at C++14.The part I looked hardest at
This makes the completion callback run on the calling thread in those paths, where it always ran on the IO thread before. I went through every in-tree caller rather than assume:
OtlpHttpClient::addSessioncloses itssession_manager_lock_scope beforeSendRequest, which the comment there says is deliberate, and the lock is recursive anyway. The handler'sCancelledreachesUnbindandReleaseSession, andReleaseSessionmoves the session togc_sessions_rather than callingFinishSession, so nothing waits.SendRequestcalls, and the synchronouswaitForResponse()waits on a predicate, which is exactly the case where the completion is recorded before the waiter arrives.FinishSession()from inside the completion callback is already covered:Cleanup()stamps the callback thread before invoking it andFinish()skips the wait for that thread.Session::SendRequestalready callscallback->OnEvent(CreateFailed, "")inline on the calling thread whenSendAsyncfails.The behaviour change a user could notice is that a cancel from
Connectingis now honoured. It used to be dropped and the request went out regardless.Tests
CancelFromCreatedCompletes,CancelFromConnectingCompletesandInvalidUrlCompletes. All three hang rather than fail without the change:timeout 25gives exit 124 and zero cases finished, and they pass in about 500 ms with it. Worth knowing for a bisect, since a regression here looks like a CI timeout rather than a red assertion.CancelFromConnectingWhilePollingCompletesis the fourth, and the only one that puts an IO thread there before the event runs. A client spawns one only afterSendAsyncreturns, so it warms the client with a completed request first, then cancels fromConnectingand stays in the handler until the IO thread has entered it too. Two things follow from that. It reports the state store race without the change and none with it, five runs out of five each way. And instrumenting both tail branches ofSendAsyncand running the whole binary shows it is the only thing that reaches theis_cleaned_recheck, which the three cases above never touch.What it stays in the handler on took a second look. It waited on
inside_events_, which is raised on the way into an event and lowered on the way out, and the event the IO thread dispatches there is a few atomics long, so sampling it every millisecond almost never caught it at two: four runs measured 30005, 30509, 30006 and 30015 ms and all passed, because the count the assertion reads is written by the thread that creates the overlap and never goes down. Waiting on that one instead leaves as soon as the overlap has happened, and the case goes from 30006 ms to 511 ms, ten runs out of ten, with the binary down from about 53 seconds to 23.5. The shorter wait is also the one that works: against a faithful revert of what this branch changed aboutsession_state_, a plain member again and the store back after the handler, ThreadSanitizer reports the race five runs out of five with it and none at all with the thirty second version, which spends that long and a great many reads of the same address between the two writes. A bound that does expire now means the overlap really did not happen, so it is recorded and checked rather than left to read as one dispatched event.ASessionTheMultiHandleRefusesIsFinishedis the third root cause, and nothing reached it before. It needs no seam around libcurl:SendAsyncdoes the whole async setup andSession::SendRequestis what starts the worker, so the case builds the operation, sends it, puts the client on a multi handle that refuses every add, and drivesdoAddSessionsitself on one thread. Reverting that finish to the plain one it had fails the case twice over, on the state it reports and on the absence of a cancel.Its overlap counters are
relaxedon purpose. Withacq_relthe two threads synchronize through the counter itself, which orders the very stores the case exists to keep unordered, and ThreadSanitizer goes quiet. A deliberate unsynchronized counter used as a control confirms it: theacq_relbuild reports neither, therelaxedbuild reports both.Checks
All 34 cases in
curl_http_testpass, three runs out of three, and the new one ten out of ten on its own. Each of them now carries a CTest timeout of 120 seconds, read back fromctest --show-only=json-v1, because what these cases catch fails by hanging: without a bound a regression stops the job rather than reporting, which happened three times while this was being written. The whole binary takes 23.5 seconds, and the two slowest cases are the ones that wait out a request timeout on purpose, at 5007 ms each.One number in here is pinned as it is rather than as it should be. Cancelling once the transfer belongs to the IO thread delivers two terminal events, one from
Cleanupand one from the completion callback, andCancelFromConnectingCompletesrequires exactly two so that a change to it is visible. One is the goal, and that is #4360, which this change does not close. A cancel fromCreatedis reported as a failed create for the same reason: the event is dispatched from the constructor, before theSessionholds the operation, so the cancel never reaches it. Moving the first events out of the constructor is the startup ordering work, not something to add here, and both are pinned rather than smoothed over. Under ThreadSanitizer the whole binary reports zero races with the change, and the new case reports the state store race five times out of five without it. Clean underOTELCPP_MAINTAINER_MODE=ONandclang-format18.1.8, clang-tidy at zero delta againstmainunder the CI filters, and IWYU reports correct includes for both changed translation units.Related
#4392 fixed the cross thread write to the easy handle on the same file and has landed, and this is rebased on it: the resolution keeps its CURLOPT_NOPROGRESS placement and its atomic AsyncData::session alongside the ordering here. #4402 is the separate deadlock,
FinishSession()called from an event the IO thread dispatches during a transfer, where the promise the wait is on can only be fulfilled further along that same thread. This change does not touch those events and does not close it. What it guarantees is narrower: the terminal event it generates itself, for an operation nothing is going to run, is dispatched after the cleanup that fulfils the promise, soFinishSession()from that one event returns.FinishFromTheCreateFailedEventReturnspins that and nothing wider.#4405 changes teardown after
Cleanup()has handed the easy resource back to the client, so the two are independent, but whichever lands second needs a real rebase rather than a metadata one because both touch the same removal path. I stacked all of #4405 on top of this branch to find out what that costs rather than leave you to work it out. Four of its eight commits conflict.doAddSessionsis one thing wanted from two ends, since this branch finishes a sessioncurl_multi_add_handlerejected and #4405 keeps that same handle off its attachment ledger, and it resolves as the union.PerformCurlMessageis another, where this branch adds a function immediately above it and #4405 changes what it returns. The rest is the test file, and that part wants judgement rather than a merge tool: both branches add cases at the same anchor whose first four lines are identical, so a mechanical union folds them into one function with twoTEST_Fheaders stacked and a variable declared twice, and it does not compile. Taken apart again and resolved, the combined tree passes the curl suite 43 of 43 under AddressSanitizer withdetect_leaks=1, the same withWITH_OTLP_RETRY_PREVIEW=ON, and under bazel.For significant contributions please make sure you have completed the following items:
CHANGELOG.mdupdated for non-trivial changes