[BUG] End the Elasticsearch exporter's wait on a read or write error

[thc1006]

Fixes #4330, from @lalitb's review of #4298.

ReadError and WriteError left completion_ at Pending. If either was the last callback, the predicate the synchronous Export() waits on could never become true and the export never returned. Both now record CompletionState::Failure like the other terminal states.

They are logged at error level, but only when they are the outcome. Recording is first writer wins, so either can arrive after a response has already succeeded, and in that case Export() still reports success. Logging unconditionally would announce a failure the caller was never told about, and logging at debug would hide the one case where the I/O error is the result, since the default log level is Warning and Export()'s failure return logs nothing of its own.

recordCompletion() therefore returns whether it was the write that decided the outcome, and the log follows that.

Two things in here are decisions rather than repairs, and I would rather put them in front of you than have them found.

The level moved from debug to error for these two. On main they were debug, and OtlpHttpClient still logs the same two states at debug behind console_debug_ and does not treat them as terminal at all. So this diverges from the sibling exporter in both level and terminality.

Treating them as terminal is a semantic call about an enum that does not define itself. The header says only error reading response and error writing request. If a client emits ReadError on a recoverable partial read and then delivers a good response, this reports failure, and IoErrorBeforeAResponseKeepsTheFailure pins that. #4330 asks for exactly this, so I have followed it, but say the word if you would rather the two exporters stayed aligned and the hang were closed some other way. The same rule applies to every error level terminal state rather than only these two: the line is printed by the call that decided the outcome, so none of them can describe a failure the caller was never told about.

Worth knowing for the risk: the in-tree curl client does not emit either state, so they can only arrive from a consumer that supplies its own HTTP client through the factory. The two new completion transitions are reachable only that way. The winner only logging rule, though, applies to the seven error states that were already terminal, so a client that reports more than one terminal event for one request now leaves one diagnostic instead of two. The bundled curl client can still do that: a setup failure dispatches ConnectFailed and then CreateFailed, which is the part of #4360 that is still open. For the consumer that supplies its own client, the export previously hung. (An earlier revision of this description tried to make that point by listing everything curl does dispatch, and got the list wrong: SendFailed and Response are dispatched too. The narrower claim is the one this change relies on.)

Tests

The cases lalitb asked for, driven by a fake HTTP client that delivers its callbacks from inside SendRequest(), which runs before Export() reaches the wait. Each case therefore also covers a completion recorded ahead of the waiter, the notification the bare cv_.wait() before #4298 would have missed:

• a response,
• a read error,
• a write error,
• a session destroyed while pending,
• a session destroyed after a response, which stays successful because the first outcome recorded is the one reported,
• a read or write error after a response, which stays successful for the same reason,
• a read or write error before a response, which stays failed, which is the case where the error line is the only diagnostic the caller gets.

Two more that widen the net past the two states being fixed:

• every terminal state ends the wait in failure. The seven that [BUG] Wait on a completion state in the Elasticsearch exporter #4298 made terminal had no test at all, so a future edit could quietly drop one back to a bare log.
• the progress states do not decide the result on their own, so a response arriving after them is still consulted.

The cases pin results and, for the terminal errors, the diagnostic that goes with them. AWinningTerminalErrorIsReportedExactlyOnce walks the nine error level terminal states and holds that each fails the export and prints its own line exactly once. NoTerminalErrorAfterAResponseIsReported walks the same nine on the losing side and holds that none of them prints anything. OnlyTheFirstTerminalFailureIsReported holds that when two failures arrive, the one that decided the outcome is the one described.

They skip at runtime rather than compiling out when async export is enabled, because gtest_add_tests registers from the source: a case missing from the binary is still handed to CTest, and a gtest filter that matches nothing exits zero, so it would report a pass without running. The skip lives in the fixture's SetUp rather than at the top of each body, because GTEST_SKIP returns and a skip inside the body leaves everything after it unreachable, which MSVC reports as C4702 and the maintainer mode jobs turn into an error.

What the coverage job measures here

None of this. code.coverage configures all-options-abiv2-preview, which turns on ENABLE_ASYNC_EXPORT, so Export() takes the asynchronous branch and the synchronous ResponseHandler is never instantiated. gcov emits no line records for it at all: in that build the coverage data for es_log_record_exporter.cc starts at line 265, where AsyncResponseHandler begins, and every line this change touches is below that. So a green Codecov result is not evidence that these cases ran. They run in the synchronous jobs, which is where the code they change is the code that executes.

Verification

Built with WITH_ELASTICSEARCH=ON and ran the exporter tests: [ PASSED ] 18 tests.. ./ci/do_ci.sh format exits 0 with no diff.

Two of those come from the half of the wait a notification is for. Every other fake here delivers its callbacks from inside SendRequest(), including the two threads of the racing case, which are joined before it returns, so the export always reached its wait with the outcome already recorded. AReadErrorAfterTheWaiterParksWakesIt and AResponseAfterTheWaiterParksWakesIt keep the handler, return, show the export still in flight, and only then deliver a callback.

Measured both ways. Deleting both cv_.notify_all() calls used to leave all sixteen cases green; it now fails those two and the other sixteen still pass, 2 of 2 runs, each failing on its own ten second wait rather than hanging. Reducing waitForResponse() to reading the current state fails them at 0 ms, 2 of 2. The export runs on a detached thread holding a shared_ptr to everything it touches, because that wait has no deadline: written with std::async the same mutation took the whole binary down at exit 124 instead of failing the cases.

The cases carry a 30 second CTest timeout. They exist to catch a wait that never returns, and without a bound a regression would stall the job rather than fail it. Verified through ctest --show-only=json-v1: all twenty one registered Elasticsearch cases report TIMEOUT=30.0, read back from ctest --show-only=json-v1.

Two things a reviewer may want to know rather than discover. compiling a case out would leave gtest_add_tests registering a phantom that CTest then reports as a pass, and the skip sits in SetUp because GTEST_SKIP returns and one at the top of a body would leave the rest unreachable, which MSVC reports under maintainer mode. And the Bazel jobs that pass --copt=-DENABLE_ASYNC_EXPORT, which is bazel.with_async_export.test and the sanitizer, legacy, noexcept and nortti entry points, compile these cases and skip them. Plain bazel.test uses the non async options, so they run there and in the CMake sync jobs.

Then removed the recordCompletion call from ReadError alone and reran that one case under a 20 second cap: it timed out rather than failing, which is the hang this closes, and confirms the case is not passing for some other reason.

The response body the success cases use satisfies the current substring check, a top level "errors": false parse, and the per operation shape #4297 now requires, which is an index acknowledgement carrying a string _index and an integer status. It did not carry _index when this was first written, so on the current #4297 every success case here would have been read as a failure once the two met.

Landing next to the other Elasticsearch changes

This test file is also touched by #4297 and #4337, and all three add a fake HTTP client to it, so any two of them conflict there. #4337 adds the same set_tests_properties(... TIMEOUT 30) line to exporters/elasticsearch/CMakeLists.txt that this one does. Whichever lands first, I rebase the others onto it and drop the duplicate rather than carry a second copy. Of the three this has the smallest production diff, 32 lines, if you want an order.

The half I had left open is closed. The error line is printed only by the call that decided the outcome, and that is now held from both sides. It needed holding: leaving the recording in place but making recordCompletion always answer that this call did not decide the outcome kept all twelve of the earlier cases green while the exporter stopped describing any failure at all, measured 12 of 12 both ways. The same change fails two of the cases now.

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 82.61%. Comparing base (60c3d11) to head (5820fbf).

Additional details and impacted files

@@           Coverage Diff           @@
##             main    #4331   +/-   ##
=======================================
  Coverage   82.61%   82.61%           
=======================================
  Files         511      511           
  Lines       20132    20132           
=======================================
  Hits        16631    16631           
  Misses       3501     3501           

Files with missing lines	Coverage Δ
...orters/elasticsearch/src/es_log_record_exporter.cc	12.22% <ø> (ø)

🚀 New features to boost your workflow:

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

[thc1006]

Context that saves working it out, since this one, #4297 and #4337 all sit on exporters/elasticsearch/src/es_log_record_exporter.cc and its test file.

Any two of the three conflict there, so whichever lands first the other two need a rebase. I will do those rebases, and there is no reason to take more than one of them.

Measured sizes, if it helps to pick a starting point. This one is 23 lines of production code and ends a wait that otherwise never returns. #4297 is 211 lines and stops a batch Elasticsearch rejected from reading as written. #4337 is 181 lines and the largest of the three. The test files are bigger than the production diffs in all three because each carries its own fake HTTP client; the second and third to land drop that copy when they rebase.

They fix separate things and none of them depends on the others, so the order is whatever suits you.