Skip to content

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

Draft
thc1006 wants to merge 1 commit into
open-telemetry:mainfrom
thc1006:fix/es-exactly-once-4338
Draft

[BUG] Report an Elasticsearch async export's outcome exactly once#4502
thc1006 wants to merge 1 commit into
open-telemetry:mainfrom
thc1006:fix/es-exactly-once-4338

Conversation

@thc1006

@thc1006 thc1006 commented Aug 31, 2026

Copy link
Copy Markdown
Member

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.

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.

Nine cases 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, and the concurrent version of each. Removing the compare exchange turns six of the nine red.

Extracted from #4337, which is 1526 lines 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.

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

@thc1006
thc1006 force-pushed the fix/es-exactly-once-4338 branch from fc104af to 779767c Compare August 31, 2026 15:13
thc1006 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Sep 1, 2026
…on identity

ForceFlush waited for options_.response_timeout_ rather than the caller's
timeout, and the timeout branch returned true whatever had happened, so every
flush that ran out of time reported success. It also compared monotonic totals
with no session identity, so a completion from a session started after the call
could satisfy a waiter for one started before it, and a batch already inside
Export() was not waited for at all.

One steady_clock deadline taken at entry, and a wait on a predicate over the set
of running session ids against a watermark. wait_until returns the predicate, so
the answer is the caller's question rather than a leftover duration. The
serialising lock is gone: each call snapshots what it waits for and publishes
nothing, so two callers were already safe side by side.

Stacked on open-telemetry#4502, which carries the exactly-once completion this accounting
depends on. That half was extracted so each pull request closes one issue and is
reviewable on its own.

Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
@thc1006
thc1006 force-pushed the fix/es-exactly-once-4338 branch from 779767c to e2d4113 Compare September 1, 2026 12:14
thc1006 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Sep 1, 2026
…on identity

ForceFlush waited for options_.response_timeout_ rather than the caller's
timeout, and the timeout branch returned true whatever had happened, so every
flush that ran out of time reported success. It also compared monotonic totals
with no session identity, so a completion from a session started after the call
could satisfy a waiter for one started before it, and a batch already inside
Export() was not waited for at all.

One steady_clock deadline taken at entry, and a wait on a predicate over the set
of running session ids against a watermark. wait_until returns the predicate, so
the answer is the caller's question rather than a leftover duration. The
serialising lock is gone: each call snapshots what it waits for and publishes
nothing, so two callers were already safe side by side.

Stacked on open-telemetry#4502, which carries the exactly-once completion this accounting
depends on. That half was extracted so each pull request closes one issue and is
reviewable on its own.

Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
@codecov

codecov Bot commented Sep 1, 2026

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 89.18919% with 4 lines in your changes missing coverage. Please review.
✅ Project coverage is 83.72%. Comparing base (58ed80d) to head (e2d4113).
⚠️ Report is 9 commits behind head on main.

Files with missing lines Patch % Lines
...orters/elasticsearch/src/es_log_record_exporter.cc 89.19% 4 Missing ⚠️
Additional details and impacted files

Impacted file tree graph

@@            Coverage Diff             @@
##             main    #4502      +/-   ##
==========================================
+ Coverage   83.24%   83.72%   +0.48%     
==========================================
  Files         521      521              
  Lines       20384    20392       +8     
==========================================
+ Hits        16967    17071     +104     
+ Misses       3417     3321      -96     
Files with missing lines Coverage Δ
...orters/elasticsearch/src/es_log_record_exporter.cc 86.81% <89.19%> (+74.60%) ⬆️

... and 4 files with indirect coverage changes

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

AsyncResponseHandler called the result callback directly from OnResponse and from
each terminal OnEvent state with no guard, and ReadError, WriteError and Destroyed
fell through a default label and called nothing. The HTTP client can deliver both
a response and a terminal event for one request, so one export could report twice,
and it can end on one of those three states and report nothing at all.

The exporter counts one finished session per export. Reporting twice overshoots
that count for the life of the exporter. Reporting never 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.

The completion line said trace span(s) in the log exporter and says log record(s)
now. The cases read that line to count outcomes, and the wording was wrong either
way.

Nine cases drive 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, and the concurrent version of each. Removing the compare exchange turns
six of the nine red.

Extracted from open-telemetry#4337, which is 1526 lines and closes two issues. What stays there
is the ForceFlush deadline and watermark accounting for open-telemetry#4336, including four
completion cases that verify this guard through the flush rather than through the
log line.

Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
@thc1006
thc1006 force-pushed the fix/es-exactly-once-4338 branch from e2d4113 to f9817df Compare September 1, 2026 13:14
thc1006 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Sep 1, 2026
…on identity

ForceFlush waited for options_.response_timeout_ rather than the caller's
timeout, and the timeout branch returned true whatever had happened, so every
flush that ran out of time reported success. It also compared monotonic totals
with no session identity, so a completion from a session started after the call
could satisfy a waiter for one started before it, and a batch already inside
Export() was not waited for at all.

One steady_clock deadline taken at entry, and a wait on a predicate over the set
of running session ids against a watermark. wait_until returns the predicate, so
the answer is the caller's question rather than a leftover duration. The
serialising lock is gone: each call snapshots what it waits for and publishes
nothing, so two callers were already safe side by side.

Stacked on open-telemetry#4502, which carries the exactly-once completion this accounting
depends on. That half was extracted so each pull request closes one issue and is
reviewable on its own.

Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
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 async exporter counts a session's completion zero or twice

1 participant