[BUG] Stop the Elasticsearch async ForceFlush reporting success without waiting

[thc1006]

Fixes #4336. Fixes #4338.

Rewritten after the second review round, so that this describes the branch as it stands rather than accumulating an appendix. The change itself is unchanged in shape; five things moved, and each is named where it belongs below.

ForceFlush waited for options_.response_timeout_ rather than the time the caller gave it, and the timeout branch left the loop without subtracting what it had just spent:

while (timeout_steady > std::chrono::steady_clock::duration::zero())
{
  if (finished_session_counter_.load(...) >= running_counter) { break; }
  auto start = std::chrono::steady_clock::now();
  if (std::cv_status::no_timeout != force_flush_cv.wait_for(
                                        lk_cv, std::chrono::seconds{options_.response_timeout_}))
  {
    break;
  }
  timeout_steady -= std::chrono::steady_clock::now() - start;
}
return timeout_steady > std::chrono::steady_clock::duration::zero();

The loop condition has already established that timeout_steady is positive, so the return on that path is true whatever happened. Every flush that ran out of time reported success. The only way to get false was to be notified repeatedly without completing until the subtraction drained the budget.

That contradicts what the method promises in es_log_record_exporter.h, return true when all data are exported, and false when timeout. The Logs SDK puts the MUST prioritize honoring the timeout over finishing all calls on the processor rather than on the exporter, whose own wording is the weaker SHOULD complete or abort within some timeout, but a return value that cannot express having run out of time gives the processor nothing to honour it with.

The change

One steady_clock deadline derived from the caller's timeout, and a wait on a completion predicate. wait_until returns the predicate, so the return value is now the answer to the question the caller asked rather than a leftover duration.

The deadline is taken at function entry rather than after the mutex, so time spent waiting for the lock comes out of the caller's budget instead of being handed back as a fresh one. A plain mutex still cannot promise a bound, but acquiring it should not add a second full timeout to the one that was asked for.

A flush with no deadline of its own gets one too. The bound is response_timeout_, which is what this path waited for before the accounting was fixed and is also the value the request itself is given, so a session outstanding when the watermark is taken has at most that long before the client owes it a terminal event. The bound is unchanged from base and the answer is what changes: running out of it no longer reports success. That also keeps this independent of the curl client work, where a transfer can currently be left with no callback at all, and it leaves ForceFlush with one wait path rather than two. An earlier revision of this branch left the no-deadline form unbounded; that was worse, because a client that accepts a request and never calls back turned a wrong true into a permanent hang.

Serialising concurrent calls was a second way to miss the deadline: force_flush_m was taken unconditionally at the top, so a second caller waited out the first one's wait however short its own timeout was. Measured at 2921 ms for a ForceFlush(20ms) behind a 3 second one.

That lock is gone rather than made timed. It protected nothing: each call snapshots the session counter it waits for and waits on its own predicate, and the wait publishes no state, so two callers were already safe side by side. It was declared in the header and used in exactly one place. Dropping it changes the layout of SynchronizationData, which is declared in the installed header, but that struct is a private member and the whole block is behind ENABLE_ASYNC_EXPORT, so it carries no ABI promise. There is no ABI diff job in CI to catch or complain about it either way. I first made it a timed acquisition instead, which ThreadSanitizer could not see through, since libstdc++ routes try_lock_until to pthread_mutex_clocklock and libtsan does not intercept it. Deleting the lock was the better answer to the same problem and that revision is not in this diff.

Removing it also means ForceFlush and Shutdown are no longer serialised against each other, which the stable Logs SDK requires them to survive, so there are two cases for the overlap: one where the shutdown settles the outstanding session and the flush is woken by that rather than by its own bound, and one where the shutdown settles nothing and the flush ends anyway. Specification issue open-telemetry/opentelemetry-specification#5248 is asking whether the exporter should carry that requirement at all, but it has not changed the current stable text.

Retirement happens under the mutex the waiter holds. It used to be an atomic counter incremented outside it, which does not lose the state but does lose the notification when it lands between the waiter's predicate check and its park. The counter itself is gone, replaced further down by ids in an ordered set, and this paragraph is about the mutex rather than about what it protects.

AdjustWaitForTimeout already maps microseconds::max() and anything that would overflow now() + timeout to zero, so zero is the sentinel for a caller that asked for no deadline.

The flush still covers the sessions that were running when it was entered, which is what the counter snapshot already meant. I asked in #4336 whether it should instead keep waiting while new exports arrive, and left the existing behaviour until you have a view.

The three the first revision left open

The first revision fixed the deadline and named three other ways this function reports success without having waited. They are the same defect from the caller's side, and two of them make the deadline fix meaningless on its own, so they are here rather than in follow-ups.

A session could be counted twice, or not at all. OnResponse and every terminal event called the result callback directly with no guard, while ReadError, WriteError and Destroyed fell through a default label and called nothing. One session could therefore finish twice, which lets the total overshoot and stay overshot for the life of the exporter, or never finish, which leaves an undeadlined flush waiting forever. Every path now goes through one CompleteOnce, a compare-exchange that reports at most once and keeps the first verdict. The switch lists every state with no default, so a state added upstream fails to compile rather than going uncounted, and the destructor reports a failure for a handler torn down without an outcome.

A completion satisfied any waiter. Both counters were monotonic totals with no session identity. A flush entering with two sessions outstanding waits for two completions; a third session started afterwards and completed, one of the original two completed, the count reached two, and the flush reported success with the other original still running. Sessions now carry an id and the running ones live in an ordered set. The snapshot is the next id to be issued and ids are issued in order, so the smallest one still running decides.

Why a set of what is running rather than a completed-sequence frontier, since both are correct. Tracking what is outstanding and waiting for it to drain is what the neighbours do: this repository's own OtlpHttpClient keeps running_sessions_ and waits for it to empty, SimpleSpanProcessor in opentelemetry-java keeps a Set<CompletableResultCode> pendingExports and returns ofAll of it, and opentelemetry-go's batch processor uses a WaitGroup. A frontier answers a stronger question, whether a contiguous prefix is complete, which is what write-ahead logs and replication need; the extra strength is what costs the unbounded buffer, because one stalled session holds back the prefix even though every completion behind it is individually known. Measured over the same traces, one stalled session with a million completions after it leaves 1000000 entries in the frontier's buffer and 2 in this one. BatchLogRecordProcessor here does use a sequence, and correctly so: its work is drained in order by one worker, where a monotone acknowledgement is exactly the right model.

Two of those neighbours also over-wait: running_sessions_.empty() and a WaitGroup both include sessions started after the call. The watermark is what keeps this one to the sessions the caller asked about.

That argument holds only while the ids keep increasing, so they are uint64_t rather than size_t. A 32 bit counter reaches its end in days at a rate this exporter is built to sustain, and the watermark taken after that point is small enough for a session that is still running to satisfy it, which is the failure that matters rather than the harmless one.

The predicate was checked against an independent oracle over 20000 random schedules, 54 million evaluations, with sessions starting, completing out of order, and flushes taking snapshots in between:

predicate	duplicate completions	reported flushed too early	reported not flushed when it was
the counter this replaces	no	9000364	0
this one	no	0	0
the counter this replaces	yes	22488236	0
this one	yes	0	0

The counter's column is what makes the zero meaningful: the same check finds the defect it replaces. The right hand column is the other half, that this does not over-wait either, and the duplicate rows are the exactly-once fix and the tracker covering each other.

A batch already inside Export() was not waited for. The session was registered after the request had been created and the whole batch serialised into its body, so a flush asked during that window snapshotted past a batch whose records had already been handed over. The Logs SDK draws the line at records received prior to the call, so they belong to it. Registration moves to the top of Export().

An earlier revision guarded that registration with a scope guard that released the id if the call gave up before a handler took it over. The guard could not reach its active destructor: the shutdown return retired by hand and disarmed it, the successful path disarmed it after SendRequest, and there was no other return between them. It is gone, the handler takes the completion by move rather than by copy, and the invariant it was watching is stated where the two exits are. Giving it something reachable to do would have meant adding null checks for an injected HttpClient, CreateSession() and CreateRequest(). Those dereferences really are unguarded today, but that is a different defect from this one and it wants its own case rather than a ride on this one.

What the diagnostics do and do not buy

Retiring an export before its terminal diagnostic keeps a flushing log handler from waiting on the session that is reporting itself, and AFlushFromInsideTheLogHandlerDoesNotWaitForItsOwnSession holds that. It is not general re-entrancy safety and the code now says so. A handler that flushes from any callback the HTTP client dispatches can wait on work only that client thread advances. That one is not introduced here and not fixed here, and #4435 has the detail.

The states a session passes through on the way to an outcome report nothing, and in particular log nothing. An earlier revision of this branch logged five of them at debug level, which the synchronous ResponseHandler has always done and the asynchronous one never has: on 60c3d11e its OnEvent is a default: break; with no progress logging at all. The session is registered before the request is handed to the client and none of those events retires it, so a handler that flushed from one waited for the export whose call stack it was standing in. Every other report in this file already retires before it logs, which is what made the omission visible: the progress cases were the one place that broke the file's own rule. The switch is still exhaustive, so a new state is still a compile error. I said in #4435 that the debug line was inherited from main; that was wrong and the issue now carries the correction.

One deliberate difference from the synchronous handler on base, worth naming rather than leaving for a reviewer to find. There, ReadError and WriteError are logged at debug and do not call recordCompletion, so a session that ends on either is never counted as finished. Here they are terminal and report a failure through CompleteOnce, because an undeadlined flush that never counts them waits for a session that has already ended. The bundled curl client does not currently produce either state, so the case that exercises it uses an injected client. #4331 is the pull request that brings the synchronous side into line; this one does not touch it.

Tests

The cases use a fake HTTP client injected through the public constructor. The wait itself is described by:

• a session that never calls back makes the flush report failure, at the caller's deadline rather than at response_timeout_,
• nothing in flight returns at once,
• a session that finished before the flush was asked for returns at once, which is the predicate being true on first evaluation,
• two exports where only one finishes is not a success,
• a completion delivered from another thread after the waiter has parked wakes it,
• a second caller arriving while the first is parked returns on its own deadline,
• a flush with no deadline returns once everything has finished, and gives up at response_timeout_ when nothing does,
• a failed export still finishes its session, so the flush completes even though the export did not,
• a flush parked when Shutdown arrives is woken by it, and ends on its own bound when the shutdown settles nothing.

Three of those fail if the change is reverted: the two that measure a flush which cannot complete, and the concurrent one, which on the old code queues behind the first caller. The others pass either way, and I would rather name that than let a list of cases look like a list of guards. They exercise paths that return before any wait, or that the old polling loop happened to get right.

Two more were added after the first review pointed at what the list above did not hold, and both were confirmed by mutating the predicate rather than by reading it. Each of these left the suite green:

if (timeout <= 0) { return flushed(); }                  // the no deadline branch
return running.empty();                                  // the whole watermark
return running.empty() || *running.begin() > watermark;  // the boundary

The first survived because the case named for the indefinite wait never parks: the fake answers from inside SendRequest(), so the predicate already holds when ForceFlush() is called. AnIndefiniteFlushParksUntilTheOutcomeArrives waits with nothing answering, checks it has not returned, and then answers. The other two survived because nothing held the opposite boundary from the substitution cases: those say a newer completion cannot finish an older flush, and ANewerSessionDoesNotHoldAnOlderFlushOpen says a newer export still running cannot keep that flush open. All three mutations are caught now.

Four cases used a 50 or 100 millisecond sleep to put an export, a completion or a second caller after the flush's snapshot. That leaves the order to the scheduler, and in the other order the newer work is inside the snapshot, where the counting model these cases exist to rule out reports a pass too. So ForceFlush() raises a counter under the mutex it already holds, immediately after reading its watermark, and the cases wait on that. It is test synchronization and nothing in the exporter reads it, which is what the header says about it.

The helper those cases wait on had the same bound as the whole CTest case, so a watermark that never arrived killed the process before the case reached its own assertion and its cleanup. Five seconds for the helper now, sixty for CTest, so an expiry names the case that failed rather than being killed from outside. The CMake comment named a case that never parks and now names the one that does.

The exactly-once cases read the completion count while the handler they retained is still alive, so its destructor had not run and a second report from there would have landed after the check. Making the destructor bypass CompleteOnce() left the suite green; the handler is released before a second read now, and three cases catch it.

The cases build in every configuration and skip in SetUp where the wait does not exist. An earlier revision compiled them out instead, which was wrong in a way worth naming: gtest_add_tests registers from the source, so they all stayed registered with CTest in the synchronous jobs, and a gtest filter matching nothing exits zero, so each reported a pass without running. Skipping in SetUp rather than at the top of each body also keeps GTEST_SKIP, which returns, from leaving the rest of a body unreachable, which MSVC reports as C4702. The helper they wait on needed a stub in the synchronous build for the same reason, inline so an unused static function does not trip the maintainer mode ratchet.

Verification

All of this is on 52470cfd, rebased onto 70fdb766.

[ PASSED ] 31 tests. with -DOTELCPP_WITH_ELASTICSEARCH=ON -DOTELCPP_WITH_ASYNC_EXPORT_PREVIEW=ON -DOTELCPP_MAINTAINER_MODE=ON, no warning in the build. The synchronous configuration registers the same 31 with CTest, runs 2 and skips 29 in SetUp, also with no warning. clang-format leaves the three files unchanged.

Both sanitizers, on the same 31:

build	result	sanitizer reports	instrumented
AddressSanitizer, detect_leaks=1	31 passed	0	34 asan_ symbols in the binary
ThreadSanitizer	31 passed	0	162 tsan_ symbols in the binary

The symbol counts are there because a sanitizer that reports nothing and a sanitizer that was not linked in look identical from the outside.

Restoring the previous ForceFlush and rebuilding the same tests fails the ones that should discriminate:

[  FAILED  ] ElasticsearchForceFlushTests.ReportsFailureWhenTheFlushDoesNotComplete (2000 ms)
[  FAILED  ] ElasticsearchForceFlushTests.PartialCompletionIsNotSuccess (2000 ms)
[  FAILED  ] ElasticsearchForceFlushTests.AConcurrentFlushKeepsItsOwnDeadline (4000 ms)
[  PASSED  ] 5 tests.
[  FAILED  ] 3 tests, listed below:

The 2000 ms is the whole response_timeout_ being spent against a 20 ms caller deadline, which is the second half of the defect.

Each of the three original defects is pinned the same way: moving the registration back below the request build turns AnExportAlreadyUnderWayIsSomethingToWaitFor red, restoring the counter comparison turns the two substitution cases red, and removing the compare-exchange from CompleteOnce() turns eight of the nine completion cases red. That last number is the reason those cases count the callback through a log handler rather than through ForceFlush(): sessions are identified rather than counted, so a repeated completion erases an id that has already gone, and every flush-based assertion passed with the guard removed.

The five things that moved in the second round are pinned the same way. A progress line restored fails EverySessionStateIsClassifiedAndReportsAtMostOnce, the bound removed fails ANoDeadlineFlushGivesUpAtTheResponseTimeout, and the unbounded wait restored hangs AParkedFlushEndsEvenIfTheShutdownSettlesNothing at exit 124.

include-what-you-use and clang-tidy were measured against main rather than in isolation, and over the test target so that the test file is compiled rather than only the library. Across all three cmake option presets the workflow builds, include-what-you-use reports the same blocks and no include changes on either tree. The async-only includes sit behind the ENABLE_ASYNC_EXPORT guard, because the presets that build without it ask for them to go while the ones that build it ask for them.

The clang-tidy limit has moved three times since this branch was opened, 133 to 113 to 83 on all-options-abiv1-preview, and each cut sets the limit to what main then reports, so there is no headroom for a branch to spend. This one spends none. Comparing its report against main's from the same day row by row, every difference is a line that shifted because the branch adds lines above it, or a row in a file the branch does not touch. Nothing in the files it does touch is new.

What it still does not fix

true means every export the call snapshotted has reported a terminal outcome, not that their batches reached Elasticsearch. A failed export reports through the internal log, so a flush can return true for a batch that was rejected. That is #3075 rather than something this changes; the header's @return says so instead of promising that all data are exported.

It is also not a statement about the transport. Every completion path publishes the outcome first: OnResponse and the terminal OnEvent states each ahead of their logging, and the handler destructor ahead of FinishSession(). That order is deliberate, since the log handler is replaceable and one that calls ForceFlush() would otherwise wait on the session its own call is still holding. The @return says that too now. It used to claim the session had ended, which the code never promised.

Shutdown(timeout) still ignores its timeout, calls CancelAllSessions() and FinishAllSessions() in order, and returns true unconditionally. Separate, and not something to read this pull request as having fixed.

Its narrower cousin is worth naming too, since this changes the code around it. is_shutdown_ is atomic, but the check in Export() and the cancellation in Shutdown() are not one step: an export that has already passed the check and is still building its session can hand a request to the client after Shutdown() has returned true. The window is the same on main, and registering the session id earlier does not widen it, since nothing moved between the check and CreateSession(). Closing it needs an admission gate the two share rather than a flag each reads on its own, which is a larger change than this one and not what the flush accounting here is about.

Landing next to the other Elasticsearch changes

exporters/elasticsearch/test/es_log_record_exporter_test.cc is also touched by #4297 and #4331, and all three add a fake HTTP client to it, so any two of them conflict there. #4331 adds a set_tests_properties(... TIMEOUT ...) line to exporters/elasticsearch/CMakeLists.txt that this one also adds, with a different bound. Whichever lands first, I rebase the rest onto it and reconcile the two.

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 83.80%. Comparing base (70fdb76) to head (52470cf).

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #4337      +/-   ##
==========================================
+ Coverage   83.25%   83.80%   +0.55%     
==========================================
  Files         521      521              
  Lines       20384    20405      +21     
==========================================
+ Hits        16969    17098     +129     
+ Misses       3415     3307     -108     

Files with missing lines	Coverage Δ
...y/exporters/elasticsearch/es_log_record_exporter.h	100.00% <ø> (ø)
...orters/elasticsearch/src/es_log_record_exporter.cc	96.72% <100.00%> (+84.50%)	⬆️

... and 1 file with indirect coverage changes

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[thc1006]

The one red is Bazel asan config, and it is not from this diff. BasicCurlHttpTests.ElegantQuitQuick in //ext/test/http:curl_http_test missed its 20 ms wall clock budget at curl_http_test.cc:940. That is the flake #4342 described and #4488 fixes; #4342 is closed, the flake is not.

This branch changes five files, all under exporters/elasticsearch/, so rather than argue it from the diff:

$ bazel query "somepath(//ext/test/http:curl_http_test, //exporters/elasticsearch/...)"
INFO: Empty results

The same job is green on main at 70fdb766, the commit this is rebased onto.

I cannot re-run a job here, so it will clear on the next push or on a maintainer re-run.