Repository navigation
Conversation
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #4395 +/- ##
==========================================
+ Coverage 86.69% 86.74% +0.06%
==========================================
Files 527 527
Lines 20902 20933 +31
==========================================
+ Hits 18119 18157 +38
+ Misses 2783 2776 -7
🚀 New features to boost your workflow:
|
|
One thing 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. Edited 16 Aug. This used to carry a second section on the eleven uncovered patch lines. It is gone rather than kept, because the comment below supersedes its numbers and one of its claims stopped being true: it said a test could not make libcurl reject a handle without more machinery than the branch was worth, and the branch now has that seam, so a case names the code it wants back instead of arranging an unusable multi handle. |
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>
…_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>
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>
FinishUnscheduled() cleaned up and then dispatched the terminal event. The operation holds the caller's handler as a bare pointer, and the only strong reference to it is the one Session::SendRequest captured in the completion callback, so Cleanup() taking that callback and letting it go is what frees the handler. The event that followed read it. AddressSanitizer reports a heap-use-after-free at the OnEvent call, reached from FinishUnscheduled, on the path where curl_multi_add_handle refuses a session. Nothing in the suite caught it because every case that reaches this path either keeps its own reference to the handler or hands SendAsync a completion that captures none, so the ownership that breaks was never assembled. The event now goes first. A handler that calls FinishSession() from it is inside a callback for this operation, so Finish() returns instead of waiting on a promise this thread has not published, which is what made the other order necessary before CallbackScope existed. DispatchEvent stores the state ahead of the handler, so the cleanup that follows still sees a terminal state and still does not report a manual cancel for something nobody cancelled. Cleaning up last also means a Finish() on another thread waits for the terminal event and the completion callback rather than for the promise alone. The new case is the only one in the file that leaves the completion callback as the sole owner of the handler, which is what every caller of Session::SendRequest does. It records its own event against its own destruction into state the case owns, so the order outlives the handler and the case fails without a sanitizer as well as with one. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
…rder is CallbackScope kept its entries in a thread_local vector, so entering one could reallocate, and it did that from a noexcept constructor where a bad_alloc calls std::terminate instead of reaching whoever asked for the request. The scopes are already stack objects living exactly as long as the entry needs to, so they can hold the links themselves: each remembers the one it displaced and puts it back on the way out. Nested dispatches, reentrancy from a different operation and other threads all behave as before, with no allocation on any event path. The header still described FinishUnscheduled as cleaning up before dispatching. It does the opposite now, for the handler's sake, so the comment said the wrong thing about the code underneath it. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
…synchronized member AsyncData::callback_thread was a plain std::thread::id written on the thread running a callback and read by Finish() and by the destructor on whichever thread called them. The accessors put a standalone atomic_thread_fence on either side of a plain load and store, which does not order anything: fences synchronize through atomic operations on a common object, and there was none, so the two conflicting accesses had no happens-before between them and the program had a data race. ThreadSanitizer stayed quiet because both accessors carried OPENTELEMETRY_SANITIZER_NO_THREAD, and the fences were compiled out under that same sanitizer, so what it was told to ignore was a bare unsynchronized access. CallbackScope already answers the question the member existed to answer, and answers it without shared state, since the scope lives on the stack frame that dispatches the callback. Cleanup() already entered one around the completion callback, right beside the two writes this removes, and Finish() already consulted it and returned before ever reaching the member, which made the second check unreachable as anything but true. The destructor now asks the same way, which also covers a handler destroying its operation from inside an event rather than only from inside the completion. FinishUnscheduled goes private with the client as a friend. It forces a terminal state, cleans up, dispatches, fulfils the promise and hands the easy resource back, and the client is the only thing that ever discovers a request nothing will run. This header is not installed by CMake but Bazel exposes it, so a public method here is API surface. include-what-you-use asked for <thread> to be dropped from both files once the member was gone, and is clean on all three of its presets. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
…ock is closed Two cases, each shown to fail without the change it covers. FinishSessionFromAnEventTheIoThreadDelivers is open-telemetry#4402: a handler calls FinishSession() from ConnectFailed, which the IO thread delivers during a transfer, and the call has to come back. Remove the callback-scope check from Finish() and it hangs, reported as the case's own message rather than as a stuck binary, because it waits on a condition to a deadline instead of sleeping for a fixed time. FinishFromTheCreateFailedEventReturns covers only the event this client generates for an operation nothing will run, which is dispatched from whichever thread found it, so it never exercised the schedule the issue is about. FinishFromAnotherThreadWaitsForTheTerminalEvent is the other direction: an outside Finish() must wait for the terminal event and the completion callback, not just for the promise. The handler parks inside the event and a third thread watches the finisher stay in, since the thread dispatching the event is the one parked and cannot also let itself out. Put the cleanup back ahead of the event and the finisher returns while the handler is still running, which the case reports. The changelog now says the deadlock is closed. The mechanism was already general: the callback scope wraps every dispatch and Finish() consults it, so the handler is covered on the IO thread's events too, and narrowing it again would only put the deadlock back. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
The cases about a session the multi handle will not take used to swap the client's multi handle for a null one and call doAddSessions. That works, but it works by handing libcurl a handle its own documentation says not to use after curl_multi_init returns null, so the rejection under test was libcurl's defence against invalid input rather than a rejection it promises. All the manual says is that a non-zero return means the add failed. doAddSessions now goes through a member the client initialises to curl_multi_add_handle, and a case that wants a refusal names the code it wants back. The three cases that forced one keep a real multi handle and ask for CURLM_BAD_EASY_HANDLE, which is a code libcurl does document for an easy handle a multi already holds, and the seam is one indirect call on a path that already takes a lock and a map lookup. The swap is still there for the state it actually describes, a client whose multi handle could not be created at all. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
…uard for The move operations are deleted alongside the copies, since a scope that moved would leave the thread's stack pointing at an object that is no longer the innermost one, and previous_ takes its value where it is declared rather than in the constructor list. Both are what the checks name, and the file now carries one warning fewer than main rather than one more. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
…is gone AsyncData::callback_thread is on main today, read and written from two threads with nothing ordering them and with both accessors marked no-thread-sanitizer, so removing it is a fix a user of the released client gets rather than something internal to this branch. The use after free this branch also fixes is not listed, because the code it lives in does not exist outside this branch and a changelog entry would claim a repair to something that never shipped. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
4784881 to
e483853
Compare
doAddSessions logged the refusal, then read GetOperation(), then finished it. The log goes through the global handler, which is replaceable application code and is not inside a callback scope for that operation, so a handler answering with Session::FinishSession() reached HttpOperation::Finish(). That is not InsideCallbackFor(this), so it waits on a promise only the FinishUnscheduled below it fulfils, on the same thread. Reading the operation after the log was the other half. A handler calling SendRequest() from there swaps the operation, and the loop then finishes the new one and leaves the refused one unsettled. FinishUnscheduled dispatches its event before it cleans up, and a handler calling FinishSession() from that event is inside a callback for the operation, so Finish() returns instead of waiting. Reporting after it is what puts the log handler inside the same protection. ARejectedSessionIsSettledBeforeItIsReported installs a global log handler that records whether the terminal event has arrived by the time the refusal is logged, and restores the previous handler and level through a scope guard. It passes with this change and fails at the ordering assertion with the report moved back above the settlement. The first version of that assertion asked only whether the handler had seen any event. That is true in both orders, because SendAsync dispatches Created during setup, and the case passed with the defect put back. It asks for CreateFailed now. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
e483853 to
6bb00bb
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>
…_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>
Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com> # Conflicts: # CHANGELOG.md # ext/include/opentelemetry/ext/http/client/curl/http_operation_curl.h # ext/test/http/curl_http_test.cc
Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com> # Conflicts: # CHANGELOG.md # ext/test/http/curl_http_test.cc
Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com> # Conflicts: # CHANGELOG.md # ext/src/http/client/curl/http_operation_curl.cc
Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com> # Conflicts: # CHANGELOG.md # ext/src/http/client/curl/http_operation_curl.cc
Five blocks in http_operation_curl.cc and one in curl_http_test.cc stated the same invariants in more lines than the code they describe. They now name the function that holds each invariant and stop, which is what dbarker asked for on open-telemetry#4327 and what ThomsonTan asked for on open-telemetry#4618. No behaviour change: curl_http_test passes 46 of 46 and clang-format 18.1.8 is clean on both files. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
The FinishUnscheduled doxygen repeated the ordering rationale that sits at the call site, so the declaration now carries the contract and the reason stays with the code. Three test comments restated themselves. Measured bar: no block in main's own curl_http_test.cc exceeds the code it describes by more than two lines. curl_http_test passes 46 of 46 and clang-format 18.1.8 is clean on both files. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
The 1.30.0 release rewrote the Unreleased section, which is the whole conflict. Both sides kept, ours after main's. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
The 1.30.0 release rewrote that section, and resolving the conflict in place left this entry inside the released block, where it reads as shipped. Rebuilt as main's file with this branch's entry inserted under Unreleased, so the only difference from main is the entry itself. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
Fixes #4390.
Fixes #4393.
Fixes #4408.
Fixes #4402.
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 inhttp_operation_curl.ccrather 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.What a second review round found
Three things, all in the code this branch adds rather than in what it inherited, and each one
is held by a case that fails without the fix.
FinishUnscheduledcleaned up and then dispatched the terminal event. The operation holds thecaller's handler as a bare pointer and the only strong reference to it is the one
Session::SendRequestcaptured in the completion callback, so the cleanup that releases thatcallback is what frees the handler, and the event that followed read it. AddressSanitizer
reports a heap-use-after-free at the
OnEventcall reached fromFinishUnscheduled. Nothing inthe suite caught it, because every case that reaches this path either keeps its own reference to
the handler or hands
SendAsynca completion capturing none, so the ownership that breaks wasnever assembled. The event goes first now.
AnUnscheduledSessionTellsAHandlerNothingElseHoldsisthe only case in the file that leaves the completion callback as the sole owner, which is what
every real caller of
SendRequestarranges, and it records its own event against its owndestruction into state the case owns, so it fails without a sanitizer as well as with one.
AsyncData::callback_threadwas a plainstd::thread::idwritten on the thread running acallback and read by
Finish()and by the destructor on whichever thread called them. Itsaccessors put a standalone
atomic_thread_fenceeither side of a plain load and store, whichorders nothing: fences synchronize through atomic operations on a common object and there was
none. ThreadSanitizer stayed quiet because both accessors carried
OPENTELEMETRY_SANITIZER_NO_THREAD, and the fences were compiled out under that same sanitizer,so what it was told to ignore was a bare unsynchronized access. The callback scope already
answers the question the member existed to answer and answers it without shared state, so the
member, its accessors and the friend declaration are gone.
Finish()consulted the scope beforeit ever reached the member, which made the second check unreachable as anything but true.
FinishUnscheduledis private now, with the client as a friend. It forces a terminal state,cleans up, dispatches, fulfils the promise and hands the easy resource back, and the client is
the only thing that ever discovers a request nothing will run.
ext/CMakeLists.txtdoes notinstall this header, but
//extglobs it, so a public method here is source API for a Bazelconsumer.
The refusal was reported before the operation it describes was settled
A third reading of
doAddSessionsfound the loop in the wrong order. It logged the refusal, then readGetOperation(), then finished it.The log goes through the global handler, which is replaceable application code and, unlike everything else on this path, is not inside a callback scope for that operation. A handler answering with
Session::FinishSession()reachesHttpOperation::Finish(), which is notInsideCallbackFor(this)and so waits on a promise only theFinishUnscheduledbelow it can fulfil, on the same thread. Reading the operation after the log is the other half: a handler callingSendRequest()from there swaps the operation, and the loop then finishes the new one and leaves the refused one unsettled.FinishUnscheduledalready dispatches its event before it cleans up, and its comment says why that matters: a handler callingFinishSession()from that event is inside a callback for the operation, soFinish()returns rather than waiting. Reporting after it is what brings the log handler under the same protection. Nothing else moved.ARejectedSessionIsSettledBeforeItIsReportedinstalls a global log handler that records whether the terminal event has arrived by the time the refusal is logged, and puts the previous handler and level back through a scope guard. With the report moved back above the settlement it fails at the ordering assertion; with the change it passes. Forty cases in the binary, all passing.Worth naming because it nearly went in wrong: the first version of that assertion asked only whether the handler had seen any event.
SendAsyncdispatchesCreatedduring setup, so that is true in both orders, and the case passed with the defect deliberately put back. It asks forCreateFailednow.What this path shares with the rest of the client, and does not fix
Telling a refused session that nothing will run its request means dispatching a terminal event, and a handler is free to answer it by starting another request on the same session.
Session::curl_operation_is astd::unique_ptr<HttpOperation>andSession::SendRequestassigns into it withreset, so that answer frees the operation whose member function is dispatching the event. AddressSanitizer reports a heap use after free, single threaded and on the first attempt.This is not introduced here. The same two stacks reproduce on
mainat58ed80d9throughConnecting, which is dispatched from insideSendAsyncand has nothing to do with this change. I have put the measurement on #4448, where the question of what a callback may call is one of the open contract items, rather than opening an issue for it.I looked at fixing it inside this pull request and decided not to. Taking ownership of the operation before finishing it removes the use after free, and it also makes
FinishSession()on another thread return without waiting, because that wait is keyed on the session still holding an operation rather than on there being outstanding work.FinishFromAnotherThreadWaitsForTheTerminalEventfails on that change, and it is right to. Both behaviours follow from the same ownership model, so choosing between them is the contract decision rather than something this change should settle on its own.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 a callback this operation dispatched is covered by a callback scope. Entering one records the operation on the calling thread, andFinish()returns rather than waiting on a completion that thread has not published yet. That covers the completion callback and every event, which is what closes [BUG] FinishSession() from an OnEvent handler deadlocks the curl client's background thread #4402.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.SendAsyncdoes the whole async setup andSession::SendRequestis what starts the worker, so the case builds the operation, sends it, and drivesdoAddSessionsitself on one thread. What refuses the add is a seam: the client reachescurl_multi_add_handlethrough a member, and a case replaces it with one that returns the code it wants. It used to swap the client's multi handle for a null one, which works, but it works by handing libcurl a handle its own documentation says not to use aftercurl_multi_initreturns null, so what was under test was libcurl's defence against invalid input rather than a refusal it promises. The manual only promises that a non-zero return means the add failed. 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
Re-measured on
9325e30e, this branch merged withmainatac7b87a8. Seven configurations, each configured and built on its own, each run the whole binary alone and once:OTELCPP_WITH_STL=CXX14,OTELCPP_MAINTAINER_MODE=ONASAN_OPTIONS=detect_leaks=1-fno-sanitize-recover=allOTELCPP_WITH_STL=CXX20OTELCPP_WITH_THREAD_INSTRUMENTATION_PREVIEW=ONOTELCPP_WITH_OTLP_HTTP_COMPRESSION=ONThe eighth configuration the earlier run used set
WITH_OTLP_RETRY_PREVIEW, and #4668 has since deleted that flag, so it is gone rather than replaced.A sanitizer that was never linked in reports nothing in exactly the way one that finds nothing does, so the three sanitizer rows are checked and not assumed:
nmcounts 30__tsan_symbols in the ThreadSanitizer binary, 35__asan_in the AddressSanitizer one and 13__ubsanin the third, none of them present in the other builds. The last two rows are checked the same way, by the three gated case names appearing in the compression binary and in no other, and by the preview macro appearing in thatbuild.ninjaand not in the default one.53 where this section used to say 38, and none of that is this branch: the file holds 53 cases, 40 of them
main's and 13 this branch's, andmaingrew the file while this sat. Of the 53, three are behindENABLE_OTLP_COMPRESSION_PREVIEW, which is the last row, and one is disabled onmain.Each run reports its own counts rather than going through CTest, because a case an
#ifdefcompiles out still gets a CTest entry and passes as zero tests run. Each of them 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 31.3 seconds, and the two slowest cases are the ones that wait out a request timeout on purpose, at 5007 and 5005 ms.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, both re-run on the merge. clang-tidy and include-what-you-use are left to the CI jobs on this head rather than quoted here, since their limits moved while this sat and a local figure from before that does not compare.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 closed here. That is a correction to what this description said before: I had scoped the claim to the terminal event this client generates itself, but the mechanism is not specific to it. A callback scope wraps every dispatch and
Finish()consults it, so a handler is covered on the events the IO thread delivers during a transfer as well, which is exactly the case the issue describes.FinishSessionFromAnEventTheIoThreadDeliversis that case, taken from the issue and made deterministic by waiting on a condition rather than sleeping; take the check out ofFinish()and it hangs. The alternative was to narrow the mechanism back to the unscheduled path, and that only puts the deadlock back for everyone else, so I would rather claim what the code does.FinishFromAnotherThreadWaitsForTheTerminalEventholds the other direction, that an outsideFinish()waits for the terminal event and the completion callback rather than for the promise alone.#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. Measured today against each other, they conflict inCHANGELOG.md,http_client_curl.ccandcurl_http_test.cc.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. The test file 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.This paragraph used to name
PerformCurlMessageas a third conflict, because this branch adds a function immediately above it and #4405 changed what it returns. #4632 has since landed that return value change onmain, so #4405 no longer carries it and the two branches now agree there. It also used to give a commit count and a combined suite result from a stacking experiment; both described a tree that no longer exists, so they are gone rather than restated.About the lines Codecov marks
Codecov reports 5 lines of this change without cover. Two are the guards in
doAddSessions()for a session whose operation or easy handle has gone beforethe queue drains; they were evaluated 39 times each and never taken, and
reaching them needs a cancel to land inside that window.
The other three are the wait in
~HttpOperation()for a transfer that is stillin flight. Those are worth naming rather than covering. The only route to them
is a second
SendRequest()on a session whose first is still running, since theclient holds a strong reference to every registered session and nothing else
destroys an operation in
Connecting,ConnectedorSending.#4431 has since landed, so that route is closed on
main:SendRequest()returns after reporting
CreateFailedrather than replacing the operation. Bythe argument above those three lines are now unreachable, and this branch is
merged with a
mainthat carries the guard.I have not removed them here, and the reason this paragraph used to give has expired. It said the removal belonged after #4618 landed. #4618 merged on 26 September and
4fe97765is an ancestor of this branch's head, so there is no competing version of that hunk left to avoid.What remains is narrower. #4618 kept the wait rather than dropping it, so the line survives in changed form, now as
async_data_ && async_data_->result_future.valid() && !CallbackScope::InsideCallbackFor(this)inHttpOperation::Cleanup. The coverage figures this paragraph used to quote were measured on a head from before that merge and the lines have moved since, so I am not restating them as current. Taking the three lines out is a change worth reviewing on its own rather than folding in here.For significant contributions please make sure you have completed the following items:
CHANGELOG.mdupdated for non-trivial changes