[BUG] Stop OTLP ForceFlush returning on the first notification and overrunning its deadline - #4357
Conversation
c2d3c4c to
db7ebb9
Compare
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #4357 +/- ##
==========================================
+ Coverage 80.86% 80.89% +0.03%
==========================================
Files 450 450
Lines 19216 19224 +8
==========================================
+ Hits 15537 15549 +12
+ Misses 3679 3675 -4
🚀 New features to boost your workflow:
|
|
The one red job is a Docker Hub timeout in the functional test setup, before anything The same job passed on the previous commit of this branch, It is also not the I do not have re-run rights on the repository. Happy to force-push the same tree to |
db7ebb9 to
6015be8
Compare
6015be8 to
1e19483
Compare
…errunning its deadline OtlpGrpcClient::ForceFlush left its wait loop on any notification without re-reading the completion counter, so one finished request reported the whole flush as complete. The loop condition is the only place that counter is read, and the break skipped it. Drop the break, let the loop condition decide, and return that condition instead of the leftover duration. Both clients waited for the configured export timeout on every iteration, so ForceFlush could block well past the deadline it was given. Bound each wait by the caller's remaining time as well. OtlpHttpClient::Shutdown calls ForceFlush(1ms) in a loop, so shutdown cost a multiple of the export timeout. The wait stays bounded and the condition is re-read on every wakeup, which is what covers a notification lost between the check and the wait. ForceFlushReturnsWithinTheCallerDeadline holds a request open with the nosend HTTP client and asserts the call returns inside its own deadline rather than the client timeout. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
1e19483 to
1d4bf6c
Compare
The mock stub ran the completion callback inline, so a request was always finished before ForceFlush() could be called and the loop under test never had anything to wait for. Holding the callback leaves the request in flight, which is all the two cases need; the counters stay private to the .cc. ForceFlushReturnsWithinTheCallerDeadline asks for 50 ms against the 10 s export timeout. ForceFlushKeepsWaitingWhenAnotherRequestCompletes leaves two requests in flight and completes one while the flush is parked, which is the notification that used to end the wait. Registration is by source text, so both cases exist in every build and opt out in the fixture rather than being compiled away.
Towards #4339. @owent confirmed the inverted comparison and suggested bounding the
wait by the caller's remaining time, which is what this does. It does not close the
issue; see "What this leaves" below.
OTLP gRPC reported the whole flush done on one completion
OtlpGrpcClient::ForceFlushleft its wait loop on any notification:std::cv_status::timeout != statusis true when the wait was notified, and theloop condition is the only place
finished_request_counteris read, so thebreakskipped it. One finished request out of many ended the wait, and the function then
returned the leftover duration rather than the predicate.
Rather than inverting the test I dropped the
breakand let the loop conditiondecide, which is what the
==form reduces to once the wait is bounded. The boundedwait_foris what covers a notification lost between the check and the wait; thebreakwas not doing that. The return is the counter predicate now.The comment above it described
running_sessions_and gc session cleanup, neither ofwhich exists in the gRPC client. It is a verbatim copy of the
OtlpHttpClientone,down to the missing space in
forever.We, so it is replaced rather than kept.Both clients waited on the exporter's timeout, not the caller's
ForceFlush(1ms)could block for the full configured export timeout. The waitinterval is
min(configured timeout, caller's remaining time)now, as suggested. Nonotification path and no lock discipline changes.
OtlpHttpClient::Shutdownis where that shows up in practice:Each of those calls could take
options_.timeout, so shutdown cost a multiple of theexport timeout rather than a multiple of 1 ms.
The result is the predicate, on both clients
Both loops used to end by returning what was left of the deadline. A completion that lands between
the last check and the last wait takes its notification with it, and the wait then consumes the rest
of the deadline and reports a timeout for work that had already finished. Each client now returns
the condition it was waiting on.
One thing I tried and backed out
OtlpGrpcClientincrementsfinished_request_counterbefore it runsgrpc_async_callback, whichis where the
ExportResultreaches the caller, so a bounded wait can see the counter satisfiedwhile the result is still on its way. Moving the increment after the callback closes that, and I
had it that way for a while.
It is not worth it here.
DelegateAsyncExportis public and takes the callback, so a caller whosecallback calls
ForceFlush()would wait for an increment that cannot happen until the callbackreturns, and the no-deadline form of that wait never ends. Trading a bounded early signal for an
unbounded self-wait is the wrong way round, and neither of the two bugs this PR fixes needs the
change. Where a request counts as finished belongs with the identity work #4339 still needs.
Test
In
otlp_http_exporter_custom_client_test.cc,ForceFlushReturnsWithinTheCallerDeadlineholds a request open with the nosend HTTPclient and asserts
ForceFlush(50ms)returns inside its deadline against a 30 secondclient timeout. It drives
OtlpHttpClient::Exportdirectly with a non-zero requestbudget, so it does not depend on
ENABLE_ASYNC_EXPORT.otlp_http_client.ccreverted tomain, test keptExpected: (elapsed) < (1000), actual: 30000 vs 1000Built and run in two configurations,
WITH_ASYNC_EXPORT_PREVIEWoff and on, six of sixpassing in both, whole file 51 ms.
The file carries the
#ifndef OPENTELEMETRY_STL_VERSIONguard its neighbours inexporters/otlp/testalready use, so like them it builds underWITH_STL=OFFand isempty in the
cmake.c++*.stl.testjobs.The gRPC half is covered through the stub.
OtlpGrpcClientAsyncDatais defined in the.cc, so no test can readfinished_request_counterdirectly, but it does not haveto:
OtlpMockTraceServiceStubwas running the completion callback inline, so everyrequest was already finished by the time
ForceFlushcould be called and the loopnever had anything to wait for. Holding the callback instead leaves the request in
flight, which is all these two cases need.
In
otlp_grpc_exporter_test.cc,OtlpGrpcExporterFlushTestPeercarries two cases.ForceFlushReturnsWithinTheCallerDeadlineasks for 50 ms against the 10 second exporttimeout.
ForceFlushKeepsWaitingWhenAnotherRequestCompletesleaves two requests inflight and completes one while the flush is parked, which is the notification that used
to end the wait.
otlp_grpc_client.ccreverted tomain, tests keptExpected: (elapsed.count()) < (5000), actual: 10000 vs 5000Value of: flushed / Actual: true / Expected: falseThe second row is the bug in one line: the flush returned success at the exact moment a
different request completed, with the one it was waiting for still in flight.
56 of 56 with
WITH_ASYNC_EXPORT_PREVIEW=ON. With it off the client tracks noin-flight requests, so the two cases skip in the fixture rather than being compiled
away.
gtest_add_testsregisters from the source text, so an#if-ed out case isstill registered with CTest and then passes without running. CTest lists both, and the
binary reports 54 passed, 2 skipped.
What this leaves
ForceFlushstill does not fully meet the contract in your point 1. Both clientssnapshot a monotonic total and wait for the finished total to reach it, so a request
that starts after the call can satisfy the snapshot while one that was pending
before it is still running. On entry
started=10 finished=8; two new requestsstart and finish; finished reaches 10 and the wait ends with the original two in
flight.
Reading both clients for that follow-up turned up four more places where the boundary
sits in the wrong spot, all of them on
mainand none of them touched here:during
PopulateRequestsees nothing;running_sessions_insert under the lock andstart_session_counter_after it;running_sessions_.empty(), which counts sessions startedafter the call, so a flush can also wait too long;
Unbindruns the caller's callback beforeReleaseSession, deliberately, because theresponse lives in an arena the session data owns.
All five want the same thing, a token issued at the exporter's
Exportentry ratherthan a counting total, which also settles the wrap a monotonic total has on a 32 bit
target. That is a change to both hot paths, so I kept it out of one you had already
scoped and wrote the set up on #4339 instead. Happy to send it as a follow-up.
Behaviour change worth knowing
OtlpGrpcClient::Shutdown()defaults to a timeout of 0, documented as "no timeout isapplied". With the
breakgone that call waits for outstanding requests instead ofreturning after the first completion, so an application that exported and exited
immediately will now see the export finish rather than be cancelled.
It does not wait indefinitely under a normal configuration: a call sets
context->set_deadline(now() + options.timeout)wheneveroptions.timeoutispositive, so each one completes or fails within the export timeout and increments the
counter either way. A caller that wants the old return-early behaviour can pass an
explicit short timeout.
One thing I noticed but did not touch
OtlpGrpcClientOptions::timeoutandOtlpHttpClientOptions::timeoutboth default toa zero duration, and the exporters fill in a real value. If a client is left with zero,
set_deadlineis skipped, and inForceFlushthe wait interval is zero as well, sothe loop spins instead of sleeping.
maindoes the same thing there, sincewait_for(lock, 0)returnscv_status::timeoutand the old!=test then did notbreak either, so this is not something the PR changes. I left it alone because the
sensible re-check interval for "no configured timeout" is a policy call, and falling
back to the caller's remaining time would reintroduce the overflow that
AdjustWaitForTimeoutexists to avoid. A sketch of the policy is on #4339 with therest of the follow-up.
Checklist
CHANGELOG.mdupdated for non-trivial changesForceFlushreturnsfalsein cases where it used to returntrue, and a defaultShutdown()now waits.Both are described above.
CI note
func_otlp_grpchas a pre-existing nondeterministic double free that aborts after thetests report passing, and it reds gcc-14 and clang-18 on
mainas well. It is notrelated to this change.