[SDK] Fix lost wakeup in BatchSpanProcessor shutdown/force-flush notify

[denizariyan]

Fixes #4373

Changes

The condvar notify_all() calls in BatchSpanProcessor were issued without holding the
mutex that guards the waiter's predicate, leaving a lost-wakeup window: if the worker
evaluated its wait_for predicate as false but had not yet parked, the notify was
missed and it only woke on the next schedule_delay.

• Hold cv_m when notifying the worker (ForceFlush wakeup, InternalShutdown) and
  force_flush_cv_m when notifying the caller (NotifyCompletion), so a concurrent
  predicate-check-then-park cannot miss the wakeup. This makes shutdown and force-flush
  completion prompt.
• The OnEnd preemptive-export notify is intentionally left as is since it's sits in the per span
  code path and and a missed wakeup there only delays a threshold-triggered export by up to one
  schedule_delay if traffic goes idle right after. The next OnEnd re-notifies the parked worker
  otherwise.
• As adding the required machinery to catch this kind of an issue in a unit test would be pretty invasive
  and not something that was done before in this project as far as I can see, I added a stress test instead.
  In my testing the issue in both ForceFlush and Shutdown paths is easily reproduced with this test pre-fix.

I provided some more details in the linked issue. #4373

For significant contributions please make sure you have completed the following items:

• CHANGELOG.md updated for non-trivial changes
  • Change is small but I assumed you would want a bug fix noted, so I did. Let me know if you rather keep it out.
• Unit tests have been added
  • Added a stress test instead. Reasoning in third point above
• Changes in public API reviewed
  • No changes in public API

[linux-foundation-easycla]

The committers listed above are authorized under a signed CLA.

• ✅ login: denizariyan / name: Deniz Ariyan (d2345a4, d8786fb)

[denizariyan]

I just realized this PR and #4365 partially overlap.

#4365 also fixes the lost wakeup in the Shutdown in BatchSpanProcessor along with similar issues in other parts of the system but does not address the lost wakeup in the ForceFlush case for BatchSpanProcessor. And this PR is roughly the other way around where it fixes the lost wakeup for both Shutdown and ForceFlush in BatchSpanProcessor but does not address the issues in other parts.

Not sure how to best resolve this, maybe I could drop the Shutdown part of this PR but then also have to remove the test for it as it will fail on this PR or if we could merge the other PR first I could also rebase on top of it. I guess another option would be to drop the BatchSpanProcessor parts from the other PR but I am a believer in first come first serve 😄

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 82.36%. Comparing base (1279a7a) to head (37d532e).

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #4382      +/-   ##
==========================================
+ Coverage   82.35%   82.36%   +0.01%     
==========================================
  Files         502      502              
  Lines       19877    19884       +7     
==========================================
+ Hits        16368    16375       +7     
  Misses       3509     3509              

Files with missing lines	Coverage Δ
sdk/src/trace/batch_span_processor.cc	86.60% <100.00%> (+0.55%)	⬆️

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[denizariyan]

Hey @dbarker, thanks for running the CI! I fixed the reported warnings/errors, could you give it another go when you get a chance?

[mateenali66]

fix looks right. re the #4365 overlap: since this PR covers both Shutdown and ForceFlush and carries the regression test, I'd drop the BatchSpanProcessor hunk from #4365 and keep its file exporter and periodic reader fixes, that splits cleanly with no ordering dependency

[mateenali66]

this window is still open since buffer_ isn't under cv_m, worst case the worker parks for the full schedule delay. worth stating that bound here?

[denizariyan]

Yes, that is what I meant with Best effort wakeup there, I'll extend the comment with the worst case outcome to make it clear.

[denizariyan]

Extended in 217e5e1

[mateenali66]

this takes cv_m while holding force_flush_cv_m. safe today because the worker releases cv_m before NotifyCompletion, but that ordering is load-bearing now, worth a comment pinning it

[owent]

I think we shouldn't lock any other mutex in ForceFlush.

1. When background is waiting when call synchronization_data_->cv.wait_for(lk, ..., it will lock synchronization_data_->cv_m and cause deadlock here. And the wakeup notification can not be sent.
2. This will make ForceFlush block for more time than timeout.

[denizariyan]

Good catch! Both of these exist in the current main but not with this PR.

1. When background is waiting when call synchronization_data_->cv.wait_for(lk, ..., it will lock synchronization_data_->cv_m and cause deadlock here. And the wakeup notification can not be sent.

On main, DoBackgroundWork() declares std::unique_lock<std::mutex> lk(cv_m) at loop-body scope, so cv_m stays held across Export() -> NotifyCompletion(). If I added the cv_m acquisition to ForceFlush() alone, you would get exactly what you describe: NotifyCompletion() takes force_flush_cv_m while the worker holds cv_m, ForceFlush() takes cv_m while holding force_flush_cv_m, and that is an ABBA deadlock.

But this PR also scopes that wait here: https://github.com/open-telemetry/opentelemetry-cpp/pull/4382/changes#diff-6f1f4caf95893b12ea6cb9203fdb5a4f383eb6f2be79ae113254986ff4d42463R192-R206

{
  std::unique_lock<std::mutex> lk(synchronization_data_->cv_m);
  synchronization_data_->cv.wait_for(lk, timeout, [this] { ... });
  synchronization_data_->is_force_wakeup_background_worker.store(false, std::memory_order_release);
}

With cv_m released before Export(), the only nesting left is force_flush_cv_m -> cv_m in ForceFlush(), and the worker never holds cv_m when it wants force_flush_cv_m. So no cycle as far as I can see.

2. This will make ForceFlush block for more time than timeout.

Similarly, with the scoping, the added blocking is bounded by the worker's cv_m hold time, which doesn't include the drain/export operations themselves, just atomic load&store + buffer_.empty() check. I think this is acceptable, WDYT?

I think now that we can guarantee there would be no lost wakeups, we could re-shape this operation to make it easier to follow and harder to break (maybe by hoisting the wakeup out of the predicate) but I would rather keep the restructuring out of this bugfix PR.

[owent]

Sorry, I may be missing something here. The main branch never tries to lock synchronization_data_->cv_m in ForceFlush, so there is no ABBA deadlock between the thread calling ForceFlush and the background thread.

Limiting the scope of the wait in the background thread does not solve this problem either: the deadlock only occurs while the background thread is waiting on synchronization_data_->cv, which still prevents ForceFlush from calling synchronization_data_->cv.notify_all() to wake it up.

In some scenarios, the timeout and schedule_delay_millis_ are set to large values, and waiting that long is not acceptable — for example, when gracefully shutting down an application.

[denizariyan]

You are right about main, my wording was sloppy, sorry. main has neither lock, so there is no ABBA there. What I meant is that adding the cv_m acquisition to ForceFlush() on top of main without the rest of the changes in this PR would create an issue, because main holds cv_m across Export() -> NotifyCompletion(), so the scoping change has to be part of the same PR. That is a statement about why both hunks are here, not about a bug in main.

On the second point though, I think (please let me know if I misunderstood what you meant) your concern rests on wait_for in DoBackgroundWork holding the mutex while parked, and it does not. cv.wait_for(lk, timeout, pred) atomically unlocks lk and blocks, and only reacquires it when it is woken or times out. So while the background thread is parked, cv_m is unlocked and ForceFlush() acquires it immediately. The mutex is held only while the predicate is being evaluated and while wait_for returns, which here is one atomic load&store plus buffer_.empty() so that is how long the added acquisition can block for.

The stress test in this PR also proves it, ForceFlushRacesWorkerPark runs 2000 rounds with schedule_delay_millis set to 10 minutes and a 1 minute watchdog that aborts the binary if ForceFlush() does not return. If taking cv_m deadlocked against a parked worker, the very first round would hang. It completes in around 1 second on Linux, macOS and Windows CI. Remove the lock and the same test fails, which is the lost wakeup this PR is fixing. I have also ran this test for over 1k rounds on my local machine without issues.

Your third point is the reason I would like to keep the lock rather than drop it. A large schedule_delay_millis_ leading to a long wait when the notification is missed is the problem this PR aims to solve. Without the lock the store and the notify_all() can land after the worker has evaluated its predicate but before it parks, the notification is lost, and the worker then sleeps the full schedule delay. With a 10 minute delay that is a 10 minute ForceFlush(), and the same applies to InternalShutdown() on the graceful shutdown path. Taking cv_m is what makes the wakeup guaranteed instead of best effort.

Please let me know if this clarifies it or if I misunderstood your concern.

[marcalff]

I think we shouldn't lock any other mutex in ForceFlush.

1. When background is waiting when call `synchronization_data_->cv.wait_for(lk, ...`, it will lock `synchronization_data_->cv_m` and cause deadlock here. And the wakeup notification can not be sent.

In my understanding, this is not an issue.

wait_for(), aka pthread_cond_wait(), internally releases the mutex while waiting for the condition, and re acquire the mutex once the condition is signaled, so the mutex is -- not -- held for the entire wait duration.

Acquiring the mutex lock before pthread_cond_signal / broacast is what makes delivering signals reliable.

[mateenali66]

with this closed the chunked wait in ForceFlush (the "must not wait for ever" workaround) is no longer needed for correctness, follow-up to simplify?

[denizariyan]

Yes, it would be nice to simplify this part. I'll create an issue for it in case someone wants to take it up as I am a bit low on bandwidth in the upcoming weeks.

[lalitb]

I believe batch log processor still has the same lost-wakeup pattern in ForceFlush(), NotifyCompletion(), and
InternalShutdown(). The metric shutdown path is already covered by #4365. I’m okay keeping this PR trace-only, but could we open and link a follow-up for the log processor so we don’t lose the remaining cases?

[denizariyan]

I believe batch log processor still has the same lost-wakeup pattern in ForceFlush(), NotifyCompletion(), and InternalShutdown(). The metric shutdown path is already covered by #4365. I’m okay keeping this PR trace-only, but could we open and link a follow-up for the log processor so we don’t lose the remaining cases?

Yes, I also briefly mentioned this in the linked issue. Created another issue for tracking the issue on the logs side #4400

[lalitb]

Thanks.

[denizariyan]

Thanks @lalitb, fyi I don't have rights to run the CI or merge. Could you do that for me?

[marcalff]

LGTM, thanks for the fix.