Skip to content

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

Draft
thc1006 wants to merge 2 commits 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 2 commits 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.73%. Comparing base (312acb6) to head (9d5224c).

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.47%   83.73%   +0.26%     
==========================================
  Files         522      522              
  Lines       20440    20453      +13     
==========================================
+ Hits        17061    17124      +63     
+ Misses       3379     3329      -50     
Files with missing lines Coverage Δ
...orters/elasticsearch/src/es_log_record_exporter.cc 86.90% <89.19%> (+39.17%) ⬆️
🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

@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>
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>
Main's open-telemetry#4071 and open-telemetry#4501 put FakeResponse, FakeRequest, FakeSession and
FakeHttpClient in an unnamed namespace at the top of this file, and this
branch already had four of those names in a second unnamed namespace lower
down. Reopening an unnamed namespace names the same namespace, so the
rebase merged both with no conflict at all and left four redefinitions.

One set now. The session and the client take a script and default to
answering the way main's did, so main's own call site needs no edit. The
script carries the handler as a shared_ptr rather than a reference, because
the cases here have to keep it and send a second event to it, and the
client keeps its on_create_session and on_cancel_all hooks, both empty by
default.

The default body stays as main wrote it. This branch does not change how
the exporter decides success, so what main's cases send still passes here.

Verified in both configurations with maintainer mode on: 12 cases, 12
passing with async export and 3 passing with 9 skipping without it.
Removing CompleteOnce's compare and exchange turns six of them red, so the
rewritten fixtures still discriminate.

Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
@thc1006
thc1006 force-pushed the fix/es-exactly-once-4338 branch from f9817df to 9d5224c Compare September 8, 2026 06:48
thc1006 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Sep 8, 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