[BUG] End the Elasticsearch exporter's wait on a read or write error - #4331
[BUG] End the Elasticsearch exporter's wait on a read or write error#4331thc1006 wants to merge 8 commits into
Conversation
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
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ 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
🚀 New features to boost your workflow:
|
69473bc to
26ea36f
Compare
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 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.
26ea36f to
4dcfc60
Compare
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.
c5e8c69 to
a8bcd0b
Compare
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.
2073625 to
206c68f
Compare
Reported by include-what-you-use, which runs with warning_limit 0.
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
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.
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.
|
Context that saves working it out, since this one, #4297 and #4337 all sit on 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. |
Fixes #4330, from @lalitb's review of #4298.
ReadErrorandWriteErrorleftcompletion_atPending. If either was the last callback, the predicate the synchronousExport()waits on could never become true and the export never returned. Both now recordCompletionState::Failurelike 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 isWarningandExport()'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
mainthey were debug, andOtlpHttpClientstill logs the same two states at debug behindconsole_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 responseanderror writing request. If a client emitsReadErroron a recoverable partial read and then delivers a good response, this reports failure, andIoErrorBeforeAResponseKeepsTheFailurepins 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:
SendFailedandResponseare 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 beforeExport()reaches the wait. Each case therefore also covers a completion recorded ahead of the waiter, the notification the barecv_.wait()before #4298 would have missed: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_testsregisters 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'sSetUprather than at the top of each body, becauseGTEST_SKIPreturns 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.coverageconfiguresall-options-abiv2-preview, which turns onENABLE_ASYNC_EXPORT, soExport()takes the asynchronous branch and the synchronousResponseHandleris never instantiated. gcov emits no line records for it at all: in that build the coverage data fores_log_record_exporter.ccstarts at line 265, whereAsyncResponseHandlerbegins, 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=ONand ran the exporter tests:[ PASSED ] 11 tests., the nine above plus the two that were already there../ci/do_ci.sh formatexits 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 reportTIMEOUT=30.0.Two things a reviewer may want to know rather than discover.
GTEST_SKIPhas no prior use in this repository, so the runtime skip is a new pattern here. And every Bazel job, including all four sanitizers, builds withENABLE_ASYNC_EXPORT, so these cases compile there but skip: they run in the CMake sync jobs only.Then removed the
recordCompletioncall fromReadErroralone 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": falseparse, 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 toexporters/elasticsearch/CMakeLists.txtthat 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
ReadErrorarriving 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.