Skip to content

[BUG] Stop the Elasticsearch async ForceFlush reporting success without waiting - #4337

Draft
thc1006 wants to merge 2 commits into
open-telemetry:mainfrom
thc1006:fix/es-forceflush-deadline
Draft

[BUG] Stop the Elasticsearch async ForceFlush reporting success without waiting#4337
thc1006 wants to merge 2 commits into
open-telemetry:mainfrom
thc1006:fix/es-forceflush-deadline

Conversation

@thc1006

@thc1006 thc1006 commented Aug 2, 2026

Copy link
Copy Markdown
Member

Fixes #4336.

ForceFlush waited for options_.response_timeout_ rather than the timeout the caller gave it, and the branch that ran out of time returned true whatever had happened:

while (timeout_steady > std::chrono::steady_clock::duration::zero())
{
  ...
  timeout_steady -= std::chrono::steady_clock::now() - start;
}
return timeout_steady > std::chrono::steady_clock::duration::zero();

The loop condition has already established that the value is positive, so every flush that ran out of time reported success.

Two more ways it answered without having waited. It 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 covered at all, because the session was registered after the request had been built.

One steady_clock deadline, taken at function entry so waiting for the mutex spends the caller's budget, and a wait on a predicate over the set of running session ids against a watermark. wait_until returns the predicate, so the return value answers the caller's question rather than being a leftover duration. Registration moves to the top of Export(). The serialising lock is gone rather than made timed: each call snapshots what it waits for and publishes nothing, so two callers were already safe side by side. Measured at 2921 ms for a ForceFlush(20ms) queued behind a 3 second one.

This is stacked on #4502. That pull request carries the exactly-once completion this accounting depends on, and closes #4338. GitHub cannot take a fork branch as a base, so until #4502 lands the diff here shows both; this half is 861 of the lines. Review #4502 first.

Twenty cases: sixteen for the flush, and four that check exactly-once through the flush rather than through the completion log line. Reverting each defect turns cases red: the deadline change turns three red, the counter comparison turns the two substitution cases red, and moving registration back below the request build turns AnExportAlreadyUnderWayIsSomethingToWaitFor red.

Not fixed here: Shutdown(timeout) still ignores its timeout, and true means every export the call snapshotted reported a terminal outcome, not that its batch reached Elasticsearch, which is #3075.

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 requested a review from a team as a code owner August 2, 2026 19:35
@thc1006
thc1006 force-pushed the fix/es-forceflush-deadline branch 4 times, most recently from c8c0e4b to bd0c772 Compare August 2, 2026 21:01
@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 83.80%. Comparing base (58ed80d) to head (c4033ed).
⚠️ Report is 9 commits behind head on main.

Additional details and impacted files

Impacted file tree graph

@@            Coverage Diff             @@
##             main    #4337      +/-   ##
==========================================
+ Coverage   83.24%   83.80%   +0.57%     
==========================================
  Files         521      521              
  Lines       20384    20400      +16     
==========================================
+ Hits        16967    17095     +128     
+ Misses       3417     3305     -112     
Files with missing lines Coverage Δ
...y/exporters/elasticsearch/es_log_record_exporter.h 100.00% <ø> (ø)
...orters/elasticsearch/src/es_log_record_exporter.cc 96.72% <100.00%> (+84.50%) ⬆️

... and 5 files 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 changed the title [BUG] Hold the Elasticsearch ForceFlush to the caller's timeout [BUG] Stop the Elasticsearch async ForceFlush reporting success without waiting Aug 3, 2026
@thc1006
thc1006 force-pushed the fix/es-forceflush-deadline branch 3 times, most recently from 6085fad to 703f2b0 Compare August 5, 2026 03:01
@thc1006
thc1006 force-pushed the fix/es-forceflush-deadline branch from fac1be4 to 648de6e Compare August 11, 2026 04:11
@thc1006
thc1006 marked this pull request as draft August 13, 2026 17:45
@thc1006
thc1006 force-pushed the fix/es-forceflush-deadline branch from 477d4ee to dbfdde9 Compare August 14, 2026 05:49
@thc1006
thc1006 force-pushed the fix/es-forceflush-deadline branch from a572304 to 80b050f Compare August 15, 2026 08:48
@thc1006
thc1006 force-pushed the fix/es-forceflush-deadline branch from 069dfde to 0eb3c55 Compare August 25, 2026 14:20
@thc1006
thc1006 force-pushed the fix/es-forceflush-deadline branch from 0eb3c55 to 52470cf Compare August 31, 2026 09:50
@thc1006

thc1006 commented Aug 31, 2026

Copy link
Copy Markdown
Member Author

The one red is Bazel asan config, and it is not from this diff. BasicCurlHttpTests.ElegantQuitQuick in //ext/test/http:curl_http_test missed its 20 ms wall clock budget at curl_http_test.cc:940. That is the flake #4342 described and #4488 fixes; #4342 is closed, the flake is not.

This branch changes five files, all under exporters/elasticsearch/, so rather than argue it from the diff:

$ bazel query "somepath(//ext/test/http:curl_http_test, //exporters/elasticsearch/...)"
INFO: Empty results

The same job is green on main at 70fdb766, the commit this is rebased onto.

I cannot re-run a job here, so it will clear on the next push or on a maintainer re-run.

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-forceflush-deadline branch from 52470cf to b3a560f Compare September 1, 2026 12:02
thc1006 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Sep 1, 2026
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-forceflush-deadline branch from b3a560f to dfb0c34 Compare September 1, 2026 12:14
…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 added a commit to thc1006/opentelemetry-cpp that referenced this pull request Sep 1, 2026
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-forceflush-deadline branch from dfb0c34 to c4033ed Compare September 1, 2026 13:14
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

1 participant