Skip to content

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

Open
thc1006 wants to merge 8 commits into
open-telemetry:mainfrom
thc1006:bugfix/es-readerror-writeerror-completion-4330
Open

[BUG] End the Elasticsearch exporter's wait on a read or write error#4331
thc1006 wants to merge 8 commits into
open-telemetry:mainfrom
thc1006:bugfix/es-readerror-writeerror-completion-4330

Conversation

@thc1006

@thc1006 thc1006 commented Aug 2, 2026

Copy link
Copy Markdown
Member

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 treatment would suit the other terminal states, but they are left alone here: no in-tree client can emit one of them after a response, so their unconditional error line is accurate today.

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. Nothing in tree changes behaviour, and for that consumer 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:

The cases pin results, not log levels. Nothing asserts on log output.

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 ] 11 tests., the nine above plus the two that were already there. ./ci/do_ci.sh format exits 0 with no diff.

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 fourteen registered Elasticsearch cases report TIMEOUT=30.0.

Two things a reviewer may want to know rather than discover. GTEST_SKIP has no prior use in this repository, so the runtime skip is a new pattern here. And every Bazel job, including all four sanitizers, builds with ENABLE_ASYNC_EXPORT, so these cases compile there but skip: they run in the CMake sync jobs only.

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 both the current substring check and a top level "errors": false parse, so they keep their meaning if #4297 lands.

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.

One gap I would rather name than have found. The error line is now printed only by the call that decides the outcome, so a ReadError arriving after a successful response no longer logs a failure the caller was never told about. Nothing asserts that half. Rewriting both sites back to an unconditional log and rebuilding leaves all nine cases green, so a regression there would be silent. Pinning it needs a captured log handler, which is the scaffolding #4297 adds to this same file, so I would rather add the assertion when these rebase onto each other than write a third copy of it now. Say if you would prefer it in this PR.

ReadError and WriteError left completion_ at Pending, so if either was the last
callback the synchronous Export() waited until its predicate could never become
true. Both now record CompletionState::Failure like the other terminal states,
and are logged at error level to match them.

Neither state is emitted by the in-tree curl client, so this only reaches a
consumer that supplies its own HTTP client through the factory, but for that
consumer the export never returned.

The new cases drive a fake HTTP client that delivers its callbacks from inside
SendRequest(), before Export() reaches the wait, so they also cover a completion
recorded ahead of the waiter: a response, a read error, a write error, a session
destroyed while pending, and a session destroyed after a response, which stays
successful because the first outcome recorded is the one reported.

Fixes open-telemetry#4330
@thc1006
thc1006 requested a review from a team as a code owner August 2, 2026 17:50
@codecov

codecov Bot commented Aug 2, 2026

Copy link
Copy Markdown

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 81.02%. Comparing base (43b656d) to head (f60d201).

Additional details and impacted files

Impacted file tree graph

@@            Coverage Diff             @@
##             main    #4331      +/-   ##
==========================================
+ Coverage   81.00%   81.02%   +0.02%     
==========================================
  Files         448      448              
  Lines       19121    19121              
==========================================
+ Hits        15488    15490       +2     
+ Misses       3633     3631       -2     
Files with missing lines Coverage Δ
...orters/elasticsearch/src/es_log_record_exporter.cc 12.22% <ø> (ø)

... 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
thc1006 force-pushed the bugfix/es-readerror-writeerror-completion-4330 branch from 69473bc to 26ea36f Compare August 2, 2026 18:51
thc1006 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Aug 2, 2026
The helper tests call IsBulkResponseSuccessful() directly, so they cannot
show that the status and the body reach it. A handler that stored a fixed
status, or an Export() that never asked for one, passes all of them.

Three cases through the exporter with a fake HTTP client: an accepted bulk
response, the rejected item from open-telemetry#4295 whose shard counter still reads
"failed" : 0, and a 500 carrying a body the parser would otherwise accept.

The fake client is the same one open-telemetry#4331 adds to this file. Whichever lands
first, the other drops the duplicate when it rebases.
thc1006 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Aug 2, 2026
The helper tests call IsBulkResponseSuccessful() directly, so they cannot
show that the status and the body reach it. A handler that stored a fixed
status, or an Export() that never asked for one, passes all of them.

Three cases through the exporter with a fake HTTP client: an accepted bulk
response, the rejected item from open-telemetry#4295 whose shard counter still reads
"failed" : 0, and a 500 carrying a body the parser would otherwise accept.

The fake client is the same one open-telemetry#4331 adds to this file. Whichever lands
first, the other drops the duplicate when it rebases.
Recording a completion is first writer wins, so a read or write error that
arrives after a response has already succeeded does not change the result
Export() reports. Logging it at error level announced a failure the caller
was never told about.

Destroyed is the existing precedent in this switch: it ends the wait the
same way and stays at debug for the same reason.

Covered by IoErrorAfterAResponseKeepsTheSuccess.
@thc1006
thc1006 force-pushed the bugfix/es-readerror-writeerror-completion-4330 branch from 26ea36f to 4dcfc60 Compare August 2, 2026 19:13
thc1006 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Aug 2, 2026
The helper tests call IsBulkResponseSuccessful() directly, so they cannot
show that the status and the body reach it. A handler that stored a fixed
status, or an Export() that never asked for one, passes all of them.

Three cases through the exporter with a fake HTTP client: an accepted bulk
response, the rejected item from open-telemetry#4295 whose shard counter still reads
"failed" : 0, and a 500 carrying a body the parser would otherwise accept.

The fake client is the same one open-telemetry#4331 adds to this file. Whichever lands
first, the other drops the duplicate when it rebases.
The seven states open-telemetry#4298 made terminal had no test. A future edit that drops
one back to a bare log would only show up as a hung export in the field.

The companion case covers the other direction: progress states must not
decide the result on their own, or a response arriving after them would
never be consulted.
Choosing between an error line that can describe an export the caller was
told succeeded, and a debug line the default log level hides, was a false
choice. recordCompletion() now reports whether it was the write that
decided the outcome, and the log follows that.

So an I/O error that ends the export says so at error level, and one that
arrives after a response has already succeeded says nothing.

Also: give the cases a CTest timeout, since a wait that stops returning
would otherwise stall the job rather than fail it; and drop the claim that
the request timeout arrives as a TimedOut event, which nothing dispatches.
@thc1006
thc1006 force-pushed the bugfix/es-readerror-writeerror-completion-4330 branch from 2073625 to 206c68f Compare August 2, 2026 20:06
Reported by include-what-you-use, which runs with warning_limit 0.
thc1006 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Aug 2, 2026
Reported by include-what-you-use on open-telemetry#4331, which has the same construct.
Adding it here rather than waiting for the same red run.
GTEST_SKIP returns, so a skip at the top of each body left the rest of
that body unreachable. MSVC reports it as C4702 and the maintainer mode
jobs turn warnings into errors, which failed the abiv2 build at lines
268 and 272. A fixture that skips in SetUp keeps every case in the
binary, which gtest_add_tests still needs, and leaves no early return
behind.
…riteerror-completion-4330

# Conflicts:
#	CHANGELOG.md
thc1006 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Aug 3, 2026
Reported by include-what-you-use on open-telemetry#4331, which has the same construct.
Adding it here rather than waiting for the same red run.
clang-tidy's misc-use-internal-linkage counts a file scope test fixture,
which took the abiv1-preview preset to 134 against a limit of 133.
thc1006 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Aug 3, 2026
Reported by include-what-you-use on open-telemetry#4331, which has the same construct.
Adding it here rather than waiting for the same red run.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

[BUG] Elasticsearch exporter can still block on ReadError or WriteError

1 participant