[BUG] OTLP ForceFlush can report success with requests pending, and waits on the exporter timeout rather than the caller's

[thc1006]

Describe your environment

main at 11fa0db0, read at source level. Both paths are inside #ifdef ENABLE_ASYNC_EXPORT.

The gRPC half below is a model rather than a run of the exporter, and here is why, because it is itself worth knowing. I did build the OTLP exporters (Debian system protobuf 3.21.12 and gRPC 1.51.1) and tried to drive ForceFlush directly through the existing friend class OtlpGrpcClientTestPeer hook. That does not compile: OtlpGrpcClientAsyncData is only forward declared in otlp_grpc_client.h and defined in otlp_grpc_client.cc, so no test translation unit can dereference async_data_ even with friendship. The counters ForceFlush decides on are unreachable from a test, which is a fair part of why this function has no coverage today, and it is something a fix will have to answer for. The Elasticsearch equivalents are #4336 and #4338; this is the same family in the two exporters most people use, which is why it is a separate report.

What is the expected behavior?

ForceFlush(timeout) returns true only when the requests it was waiting for have finished, and returns within the timeout it was given.

What is the actual behavior?

OTLP gRPC returns success when any one request completes. OtlpGrpcClient::ForceFlush:

while (timeout_steady > std::chrono::steady_clock::duration::zero() &&
       request_counter > async_data_->finished_request_counter.load(std::memory_order_acquire))
{
  std::chrono::steady_clock::time_point start_timepoint = std::chrono::steady_clock::now();
  if (std::cv_status::timeout !=
      async_data_->session_waker.wait_for(lock, async_data_->export_timeout))
  {
    break;
  }
  timeout_steady -= std::chrono::steady_clock::now() - start_timepoint;
}
return timeout_steady > std::chrono::steady_clock::duration::zero();

std::cv_status::timeout != status is true when the wait was notified, so any notification leaves the loop without re-checking the counter, and the return is the leftover duration rather than the predicate.

A model that keeps the loop and both branch conditions exactly, with two requests where one completes:

started=2 finished=1 ForceFlush returned true after 50 ms

That is a model, not the exporter. What I can state about the exporter itself is structural: the counter is only re-read by the while condition, and the break skips it.

The comment above that break refers to running_sessions_ and to cleaning up gc sessions, neither of which exists in otlp_grpc_client.cc. Both are OtlpHttpClient members, and the comment is a verbatim copy of the one in otlp_http_client.cc, down to the missing space in forever.We. The HTTP original reads:

if (std::cv_status::timeout == session_waker_.wait_for(lock, options_.timeout))
{
  cleanupGCSessions();
}
else if (finished_session_counter_.load(std::memory_order_acquire) >= wait_counter)
{
  break;
}

so it breaks on a notification only if the counter predicate also holds. The gRPC copy dropped that else if and kept a bare break. The break is not guarding the lost-wakeup window the comment describes; the bounded wait_for is.

Both wait on the exporter's timeout rather than the caller's remaining time. gRPC waits async_data_->export_timeout, HTTP waits options_.timeout. A ForceFlush(1ms) can therefore block far longer than asked. The HTTP loop does subtract the elapsed time on every path, so unlike gRPC it terminates and returns false correctly; its problem is the overrun, not a false success. OtlpHttpClient::Shutdown calls ForceFlush(std::chrono::milliseconds{1}) in a loop, and each call can currently take up to options_.timeout.

The spec is explicit that a processor MUST prioritize honoring the timeout over finishing all calls, and that an exporter's Export MUST NOT block indefinitely.

Additional context

Two design questions I would rather settle with you before writing code, since they change the shape of the fix.

Should ForceFlush wait only for what was in flight when it was entered? Both implementations snapshot a counter at entry, so that is the current intent, and it is what keeps an indefinite flush from being starved by a steady stream of new exports. Confirming it would be useful, because the HTTP loop also breaks on running_sessions_.empty(), which is the other reading.

Can the gRPC completion path take session_waker_lock? The counters are incremented and notify_all() called without it, so a completion landing between the waiter's predicate check and its park is missed. For gRPC that looks safe to fix directly, since running_calls_lock is released before that point. For HTTP it is not: ReleaseSession notifies while holding session_manager_lock_, and ForceFlush takes session_waker_lock_ and then session_manager_lock_, so making the notifier also take session_waker_lock_ inverts the order. HTTP would need a bounded re-check interval clamped to the caller's deadline instead of one sleep to it. That asymmetry is a real constraint rather than a style preference, and it is the main reason I would send these as two PRs rather than one.

On blast radius: no existing test asserts the return value of ForceFlush for either exporter, so nothing should flip. The exposure is wall clock timing, and the user visible change is that callers who get true today while exports are pending will start getting false. That is the point of the fix, but it is a behaviour change in the two most used exporters and belongs in the CHANGELOG.

One thing to know when reading CI on any PR that touches this: func_otlp_grpc has a pre-existing nondeterministic double free that aborts after the tests report passing, and it reds gcc-14 and clang-18 on main as well. It is not related.

I am happy to do both fixes once you have a view on the two questions.

[owent]

1. ForceFlush(timeout) returns true only when all requests that were pending before the call have completed.
2. Regarding std::cv_status::timeout != status — that's indeed a bug. It should be std::cv_status::timeout == status.

Most of the time, the condition variable wakes the waiting thread when exporting finishes. However, signals can occasionally be lost because condition checking and locking are not atomic in most STL implementations. To avoid an infinite loop, we wait periodically. Using min(options_.timeout, rest_time) as the wait interval would be a better choice.

In OtlpGrpcClient, when session_waker_lock is held, calling notify_all() releases the lock so that waiting threads can be woken up. In OtlpHttpClient, the corresponding lock is session_waker_lock_, not session_manager_lock_. The latter is only used to ensure thread-safe access to running_sessions_.

Please feel free to open a PR to fix this. We'd be happy to review it!

[thc1006]

Thanks, that settles both questions.

PR: #4357

On the ==: I ended up dropping the break rather than inverting it. Once the
interval is clamped, a bare break on the timeout branch would end the wait while the
caller still had time left, so the part that matters is the counter check on the other
branch, and the loop condition already does exactly that on every wakeup. That is the
HTTP shape with the cleanupGCSessions() branch removed, since the gRPC client has no
gc list. Say the word if you would rather have the explicit == plus counter check
for symmetry.

The wait interval is min(configured timeout, caller's remaining time) in both
clients now. No notification path and no lock discipline changes, so the ordering
asymmetry I asked about in question 2 does not come up.

Two corrections to what I wrote in the issue.

otlp_http_client.cc contains no ENABLE_ASYNC_EXPORT at all. The client takes
max_running_requests as a runtime argument and is synchronous only when it is zero;
what is gated is the caller, OtlpHttpExporter::Export, which passes 0 in a non-async
build. So my "both paths are inside #ifdef ENABLE_ASYNC_EXPORT" was right about the
gRPC client and wrong about the HTTP one. The fix and its test are compiled into every
build.

I also wrote that the HTTP client had an overrun but no false success. That was wrong,
and it is the one thing the PR does not fix. Both clients snapshot a monotonic total
and wait for the finished total to reach it, so a request that starts after the call
can satisfy the snapshot while one that was pending before it is still running: entry
started=10 finished=8, two new requests start and finish, finished reaches 10, and the
wait ends with the original two in flight. That misses your point 1.

Fixing it needs request identity rather than counting, in both hot paths, so I left it
out of a change you had already scoped and left the issue open. Happy to send it as a
follow-up if you want it.

[thc1006]

One correction to my last comment. The fix is compiled into every build, the test is
not. otlp_http_exporter_custom_client_test.cc sits inside
#ifndef OPENTELEMETRY_STL_VERSION, which api/CMakeLists.txt defines for every
WITH_STL value, so the file is empty in the cmake.c++*.stl.test jobs. That guard is
the existing convention in the OTLP exporter test files rather than anything this PR
adds, and WITH_STL=OFF is where I ran it. I should have said the fix, not the fix and
its test.

[thc1006]

Reading both clients again for the identity work, the counter substitution I described is
not the only place the boundary sits in the wrong spot. Recording the rest here so the
follow-up covers the set rather than the one case. All of these are on main today, and
#4357 changes none of them.

A request is not registered until well after the exporter has it.
OtlpHttpExporter::Export builds the arena, runs PopulateRequest, and creates the
response before it calls OtlpHttpClient::Export; the session joins running_sessions_
later still, in addSession. The gRPC path has the same shape through
DelegateAsyncExport. A flush that lands while a batch is being serialised sees nothing,
even though the exporter was handed that data before the call.

The HTTP registration is two steps. In addSession the session_manager_lock_ scope
closes, and start_session_counter_.fetch_add comes after it. A flush that reads the
counter in between takes the old value for a session that is already in
running_sessions_, so that request falls outside a snapshot it should have been inside.

The HTTP wait can also be too long. The loop leaves on running_sessions_.empty(),
which includes sessions started after the call. A flush whose own snapshot is already
satisfied can be held by a later export, and under a steady stream it need not finish at
all. Same contract, other direction.

Publishing a completion and releasing the transport cannot be one step.
ResponseHandler::Unbind runs the caller's callback and only then calls ReleaseSession,
which is where the session leaves running_sessions_, the finished counter moves, and the
notify happens. The ordering is deliberate, since the response the callback reads lives in
an arena owned by the session data. It does mean a callback that calls ForceFlush() waits
for a session whose release sits below it on its own stack, and the no-timeout form of that
wait does not end. Moving ReleaseSession up would fix the wait and break the lifetime, so
a tracker wants three phases rather than two: retire the token and notify, run the external
callback, release the transport resources.

One more, on the wait interval rather than the boundary. min(configured, remaining) is
right whenever the configured timeout is positive, but OtlpGrpcClientOptions::timeout and
OtlpHttpClientOptions::timeout both default to a zero duration, and a client left at that
value gets wait_for(lock, 0) and spins. main does the same, so it is not new, but it
would be good to settle the policy in the same change: fall back to the caller's remaining
time when nothing is configured, with a bounded recheck rather than the raw remaining, since
an unset caller timeout is duration::max() here and that is the overflow
AdjustWaitForTimeout exists to avoid.

A token issued at the exporter's Export entry and retired in the first of those three
phases closes all four boundaries, the substitution, and the wrap a monotonic total has on a
32 bit target.

For acceptance, the case from point 1: A and B pending at entry, C and D start and finish
afterwards, and the flush still waits for A. Worth one per client, plus one that pauses
inside PopulateRequest for the registration boundary. Happy to be told any of these belong
somewhere other than this issue.

[thc1006]

One scoping question before I write the identity change, because getting it wrong means
writing it twice.

OtlpGrpcClient can be shared. The trace, metrics and log exporters each take a
const std::shared_ptr<OtlpGrpcClient> & constructor and a matching factory overload, and
all three ForceFlush implementations hand the caller's timeout straight to that one client.
The counters it waits on, start_request_counter and finished_request_counter, are a
single pair on the shared OtlpGrpcClientAsyncData.

So on a shared client a trace flush waits for log requests:

trace requests all finished
one log request still in flight
trace_exporter.ForceFlush(20ms)
  -> the client-wide snapshot is not satisfied
  -> waits for the log request, and can return false

The error is in the safe direction, a spurious timeout rather than a premature success, so it
is not urgent on its own. It matters here because a per-request token has to be scoped to
something, and the two answers lead to different code.

If a shared client's flush is meant to cover everything on that client, then the token needs
no owner and the API documentation should say so, since a caller reading
SpanExporter::ForceFlush would not expect it.

If each exporter's flush should cover only its own data, the token needs an owner, and the
key already exists: every exporter creates its own OtlpGrpcClientReferenceGuard and passes
it to AddReference. A snapshot taken against that guard, with Shutdown keeping the
client-wide view, would fall out of what is already there rather than adding a new concept.

Which of those did you have in mind? I would rather ask now than pick one and rework it.

Two smaller notes while I am here, both already on the list above rather than new.

The three-phase completion only helps the terminal logs. Created, Connecting and
Sending are dispatched while the request genuinely is in flight, so a log handler that
calls ForceFlush() from one of those is asking to wait for something unfinished, and no
tracker ordering can make that safe. If the internal log handler is allowed to re-enter SDK
lifecycle calls at all, that part has to be a documented contract rather than an ordering
fix. #2024 is about the same singleton but a different property, its lifetime, so I have not
added this there.

kDefaultMaxResponseSize is 4 MiB in the bundled curl client, so the default path is
bounded. A custom HttpClient has no equivalent, and the Elasticsearch exporter then copies
the whole body, parses it, and can put it in a log line. That is an argument for bounding
what the exporter logs rather than for anything in the identity work.