[BUG] Report an Elasticsearch async export's outcome exactly once

[thc1006]

Fixes #4338.

AsyncResponseHandler calls the exporter's result callback directly from OnResponse and from each terminal OnEvent state with no guard, and ReadError, WriteError and Destroyed fall through a default label and call nothing.

The HTTP client can deliver both a response and a terminal event for one request, so one export can report twice. It can also end on one of those three states and report nothing at all. The exporter counts one finished session per export, so the first overshoots that count for the life of the exporter, and the second leaves a flush waiting on a session that has already ended.

Every path goes through one CompleteOnce now, 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.

Every path that reports also retires the session before it writes anything a user can replace. OnResponse() already did; the callback CompleteOnce() invokes did not, and logged its own line first, so a handler that called ForceFlush() from that line waited for the session reporting to it. Measured at 2000276us before the reorder.

One thing comes with it that is not strictly the fix. The completion line said trace span(s) in the log exporter; it says log record(s) now. The cases below read that line to count outcomes, and the wording was wrong either way.

Thirteen cases run in the async build in es_log_record_exporter_test.cc, driven by a fake HTTP client through the public constructor: each terminal ordering a real session can produce, a response and a teardown event in both orders, the concurrent version of each, and four that time a re-entrant flush. Removing the compare exchange turns six of the thirteen red. The sync build runs three and skips ten.

Extracted from #4337, which is +1399 and closes two issues. What stays there is the ForceFlush deadline and watermark accounting for #4336, including four completion cases that verify this guard through the flush rather than through the log line, which need that accounting to work.

Two open issues this sits next to

#4435, a log handler that calls ForceFlush() re-entrantly. Not closed here. The two shapes that issue describes, flushing from a callback the client dispatches and flushing before the request has been handed over, are untouched. What is closed is the narrower half it names, an export's own terminal diagnostic: every path that reports now retires the session before it logs, and four cases hold that by timing the re-entrant flush.

#4336, ForceFlush() reporting success on its own timeout and ignoring the caller deadline. Also untouched. It matters here only because those four cases must not depend on it: the bound comes from the timeout they ask for rather than from response_timeout_, so a fix there leaves them failing on a broken ordering instead of quietly passing.

For significant contributions please make sure you have completed the following items:

• CHANGELOG.md updated for non-trivial changes
• Unit tests have been added
• Changes in public API reviewed

[codecov]

Codecov Report

❌ Patch coverage is 89.74359% with 4 lines in your changes missing coverage. Please review.
✅ Project coverage is 86.78%. Comparing base (b4257f0) to head (8ffbea6).

Files with missing lines	Patch %	Lines
...orters/elasticsearch/src/es_log_record_exporter.cc	89.75%	4 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #4502      +/-   ##
==========================================
+ Coverage   86.52%   86.78%   +0.27%     
==========================================
  Files         525      525              
  Lines       20475    20488      +13     
==========================================
+ Hits        17713    17778      +65     
+ Misses       2762     2710      -52     

Files with missing lines	Coverage Δ
...orters/elasticsearch/src/es_log_record_exporter.cc	86.90% <89.75%> (+39.17%)	⬆️

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

[om7057]

Reviewed this against the sync-path counterpart of this exact accounting (the finished_session_counter_/force_flush_cv machinery in #4523's ForceFlush fix). The CompleteOnce() compare-exchange is the right shape: it closes both the double-report case (response + terminal event both firing) and the destructor gap (a handler torn down with no outcome at all previously left a flush waiting on a session that would never finish). Confirmed the switch is genuinely exhaustive against all 15 SessionState values, and the concurrency tests (ConcurrentTerminalEventsReportOnce, AConcurrentResponseAndTerminalEventReportOnce) actually exercise the race the atomic exists for, not just the sequential orderings.

One thing I want to flag: the comment on AFlushFromTheShutdownErrorDoesNotWaitForItsOwnExport says "The export is registered before the shutdown check, so reporting the refusal before retiring it makes a flushing handler wait for the Export() that is calling it." That doesn't match what actually happens on this path: session_counter_.fetch_add() in Export() only runs after the isShutdown() check passes, so a refused export is never registered at all. The reason the re-entrant ForceFlush() call here doesn't hang isn't retirement ordering, it's that (a) nothing was ever counted for this export, and (b) force_flush_m is a std::recursive_mutex, so the same thread re-entering it from inside the log call it's already holding succeeds instead of deadlocking. The test itself pins real, correct behavior, but the comment explaining why it passes looks copied from the response/session-retirement reasoning above it rather than describing this specific path. Worth a one-line fix so a future reader isn't misled about which mechanism is doing the work here.

Nothing else stood out as incorrect.

[thc1006]

You are right, and chasing it found something worse than the comment.

On the comment: isShutdown() returns before session_counter_.fetch_add(), so a refused export is never registered. What I wrote was the reverse of what the code does. Fixed.

On your (b): force_flush_m is a std::recursive_mutex, but I do not think recursion is what carries this path. Export() takes no lock before the refusal log, isShutdown() is a plain read of is_shutdown_, and Shutdown() has already returned by the time the handler is installed. So nothing holds it when ForceFlush() re-enters. Your (a) is the whole mechanism, and it is now what the comment says.

Then I tried to prove that with a mutation, and the test did not fail.

Registering the export before the shutdown check, which is exactly the hang the case is named for, left it green. It went from 0 ms to 2000 ms, the kShortResponseTimeoutSeconds the fixture sets, and still reported OK. ForceFlush() returns timeout_steady > 0, which stays true when it breaks out on its own condition variable timeout, so EXPECT_TRUE(flushed()) cannot tell a flush with nothing to wait for from one that waited the full timeout.

AFlushFromInsideTheLogHandlerDoesNotWaitForItsOwnSession had the same hole. Logging before CompleteOnce() retires the session also left it green at 2000 ms.

So the handler now times the re-entrant flush and both cases bound it at half the response timeout. Measured on the same tree:

mutation	before	now
register before the shutdown check	passes, 2000 ms	fails, the flush waited 2000099us
log before CompleteOnce()	passes, 2000 ms	fails, the flush waited 2000108us

Unmutated, 12 of 12 pass in the async build and 3 pass with 9 skipped in the sync one, both with maintainer mode and no warnings.

The branch is also rebased onto 1525d6a5 since your review, so the conflict marker is gone.

Thanks for reading it closely enough that the wrong sentence was worth chasing. That ForceFlush() reports success on its own timeout looks like a real reporting problem rather than a test artefact, but it belongs with the flush semantics work rather than here, so I have left it alone in this pull request.

[thc1006]

One more, from carrying your point further: the same rule was broken on a third path, and none of the cases were watching it.

OnResponse() reports through CompleteOnce() before it logs, which is what the sibling case pins. But the callback CompleteOnce() invokes writes its own line first and counts the session finished afterwards:

if (result != kSuccess) { OTEL_INTERNAL_LOG_ERROR("... ERROR: Export ..."); }
...
synchronization_data->finished_session_counter_.fetch_add(1, ...);
synchronization_data->force_flush_cv.notify_all();

So a handler watching ERROR: Export rather than Logs were not written waits for the session reporting to it. Pointing the existing handler at that needle measured 2000276us, the same full response timeout.

Counted and woken first now, then logged, with a case for that message. Inverted, it fails at 2000158us; as it stands, 13 of 13 pass in the async build and 3 pass with 10 skipped in the sync one, both maintainer mode, no warnings.

That line is on main rather than something this pull request introduced, but this is the pull request that states the rule, so applying it to every path that reports seemed better than leaving one exception behind.

For the record on the other point: ForceFlush() returning true when it gives up on its own condition variable is also unchanged by this pull request, so I have left it where it is rather than widen this one.

[thc1006]

Third one, and it was the case you singled out.

AHandlerDestroyedWithoutAnOutcomeStillFinishes asserted EXPECT_TRUE(ForceFlush(...)) too. Deleting CompleteOnce() from ~AsyncResponseHandler(), which is the whole destructor gap, left it green at 2000 ms. So the case for the half of this you called out could not fail either. It times the flush now, through one helper the other three share.

Every ordering in this pull request is pinned by a mutation that has to fail:

inverted	result
register before the shutdown check	the flush waited 2000129us
log before CompleteOnce() in OnResponse()	the flush waited 2000068us
callback logs before it retires	the flush waited 2000120us
no completion in ~AsyncResponseHandler()	the flush waited 2000434us

Unmutated: 13 of 13 pass in the async build, 3 pass with 10 skipped in the sync one, both maintainer mode with no warnings, and Bazel TSan runs the 13 with no data race.

Two other things while I was in here.

The comments are cut back to describe the code rather than argue for it, none longer than what it annotates. The longest block that remains is the /** */ on CompleteOnce(), which is the file's existing documentation style.

The two log lines the callback change moves also said trace span(s) in a log record exporter. I corrected them to log record(s) since they were being touched. That is observable output, so I would rather name it here than have it turn up unexplained in the diff.

[thc1006]

One more, and it was the bound itself.

kFlushDidNotWaitUs was derived from options_.response_timeout_, because that is what a waiting flush actually burns. But it only burns it because ForceFlush() waits on the exporter's response timeout instead of the caller's deadline, which is #4336. Fix that and a broken ordering would wait the 20ms the case asked for, land under the bound, and all four of these would quietly stop failing.

So the case now asks for 200ms and bounds at half of it, which separates the two outcomes whether or not the deadline is honoured. Checked by applying a caller-deadline fix to ForceFlush() and re-running the mutation on top of it:

tree	result
deadline honoured, ordering intact	passes, 0.01s
deadline honoured, destructor stops completing	fails, the flush waited 200110us
deadline as it is today, destructor stops completing	fails, the flush waited 2000434us

All four orderings still fail when inverted on the branch as it stands: 2000120us, 2000121us, 2000108us, 2000108us. Unmutated, 13 of 13 in the async build, 3 with 10 skipped in the sync one, no warnings, and Bazel TSan runs the 13 with no data race.

On issues, since this touches two that are already open rather than needing new ones:

• [BUG] Elasticsearch async ForceFlush reports success on timeout and ignores the caller deadline #4336 is the ForceFlush() deadline and return value. Nothing here changes it; the bound is now written so it survives a fix.
• [BUG] A log handler that calls ForceFlush can deadlock the export that is logging #4435 is a log handler that calls ForceFlush() re-entrantly. This does not close it: the two shapes it describes, flushing from a client callback and flushing before the request is handed over, are still there. What it does close is the narrower half that issue calls out, an export's own terminal diagnostic, and the three cases here are the regression test for it.

I could not find a third thing worth filing. The remaining items I ran into are covered by #4359 for Shutdown, #4362 for the synchronous wait, and #4402 for FinishSession() from a callback.