Skip to content

asynchronous_sink flush() can hang forever (lost wakeup in atomic_based_event) #255

Description

@Burgch

asynchronous_sink flush() can hang forever (lost wakeup in atomic_based_event)

Summary

boost::log::core::flush() (via asynchronous_sink::flush()) can hang forever.
The sink's dedicated feeding thread ends up parked in
boost::log::aux::atomic_based_event::wait() after a wakeup that was requested
was lost, and the flushing thread then waits indefinitely for that feeding
thread. It is a genuine lost-wakeup deadlock, not a livelock or a
lock-ordering cycle.

Affected versions / platforms

  • Introduced in 1.78 by the rewrite of the event primitive
    (libs/log/src/event.cpp, commit 28822ba, "Ported futex-based event
    implementation to Boost.Atomic").
  • Present, byte-for-byte unchanged, through 1.89.0 and current develop.
  • The bug lives in atomic_based_event — the implementation selected whenever
    BOOST_ATOMIC_HAS_NATIVE_INT32_WAIT_NOTIFY == 2 (a native atomic wait/notify:
    futex on Linux, WaitOnAddress on Windows 8+). That first branch of
    event.hpp wins on both x86-64 Linux and modern Windows, so both platforms
    run the same buggy class. Reproduced live on x86-64 Linux (stall shown
    below). Modern Windows compiles the identical code path but was not
    independently made to stall here (the Windows build under test already carried
    the fix on that path; see below).
  • winapi_based_event — the distinct implementation selected only on
    pre-WaitOnAddress Windows (or when a native atomic wait/notify is otherwise
    unavailable) — has the same fast-path defect in its own set_signalled().
    Reproduced live on Windows 11 x64 by forcing that path. sem_based_event
    (macOS / POSIX semaphore fallback) is not affected.
  • The same logical flaw exists on any weakly-ordered architecture using these
    paths.
  • Compiler is not a factor: gcc 14.2 and 14.3 emit identical instructions for the
    faulting function; MSVC 14.3 exhibits the same behaviour.

Configuration

asynchronous_sink<...> with the default unbounded_fifo_queue and a dedicated
feeding thread (the default), flushed via core::flush() while other threads log.

Root cause

Three pieces of shared state cooperate:

  1. atomic_based_event m_event — a single 32-bit word m_state (0 = not
    signalled, 1 = signalled), backed by boost::atomic<uint32>::wait()/notify_one()
    (futex on Linux).
  2. boost::atomic<bool> m_interruption_requested — the queue's "wake up and stop
    blocking" flag.
  3. the record queue / m_FlushRequested — the flush predicate.

The feeding thread parks in dequeue_ready():

while (true) {
    m_event.wait();                                          // park
    if (m_interruption_requested.exchange(false, acquire))   // predicate A
        return false;
    if (m_queue.try_pop(rec)) return true;                   // predicate B
}

flush() calls interrupt_dequeue():

m_interruption_requested.store(true, release);   // (I1) publish predicate
m_event.set_signalled();                          // (I2) wake the feeder

and blocks on m_BlockCond until the feeder services the flush.

The event, since 1.78:

void atomic_based_event::wait() {
    while (m_state.exchange(0u, acq_rel) == 0u)   // consume signal
        m_state.wait(0u, relaxed);                // futex wait
}

void atomic_based_event::set_signalled() {
    if (m_state.load(relaxed) != 0u)              // (A) already signalled?
        atomic_thread_fence(release);             //     fence only, NO notify
    else if (m_state.exchange(1u, release) == 0u) // (B) 0 -> 1
        m_state.notify_one();
}

Branch (A) — "if already signalled, skip the notify" — is unsound because the
event is paired with external predicates. It relies on the invariant
"m_state == 1 implies a pending wakeup a waiter will still act on", which holds
for a self-contained event (where the wait-word is the predicate) but not here.

The interleaving that strands the feeder (all on x86):

  1. A prior enqueue left m_state == 1.
  2. The feeder's wait() does exchange(0) → reads 1 → returns, pops the record,
    loops back, finds the queue empty, and heads for wait() again.
  3. interrupt_dequeue() runs: (I1) stores the predicate, then (I2)
    set_signalled() takes branch (A) because m_state is still 1 (the feeder
    hasn't reset it yet) → release fence only, no notify_one.
  4. The feeder's wait() exchange(0) reads 1 and returns — consuming the stale
    signal — then checks m_interruption_requested. If (I1) is not yet visible
    (the x86 StoreLoad window), it reads false, finds the queue empty, loops,
    exchange(0) reads 0, and parks on m_state == 0.
  5. No further set_signalled() will come: the flushing thread already made its
    one call (which took the no-notify branch) and is now blocked on m_BlockCond.

End state (confirmed live via gdb): m_state == 0,
m_interruption_requested == 1, m_FlushRequested == 1, feeder asleep. The
wakeup edge was requested and lost. It is self-sustaining with a single stuck
thread
; any other threads pile up behind the core's write lock (held across the
flush) and are victims, not causes.

Two independent properties of the pre-1.78 unconditional exchange were lost:

  • A StoreLoad barrier. On x86 a lock-prefixed RMW drains the store buffer,
    forcing (I1)'s store visible before the notify decision. The fast path replaced
    the RMW with a plain load.
  • Wake-on-already-consumed. With an unconditional RMW, this exchange(1) and
    the waiter's exchange(0) are totally ordered in m_state's modification
    order, so a wake is guaranteed even when the prior signal was just consumed.
    "Skip notify if already 1" abandons that guarantee.

Which implementation runs where

event.hpp selects the implementation at compile time, and the first matching
branch wins:

  1. BOOST_ATOMIC_HAS_NATIVE_INT32_WAIT_NOTIFY == 2atomic_based_event. This
    is a native atomic wait/notify — a futex on Linux and WaitOnAddress on
    Windows 8+
    . So both x86-64 Linux and modern Windows compile this class; it is
    the buggy path and the primary target of the fix. (A Windows 11 probe measured
    the macro == 2 and has_native_wait_notify() == true; lowering
    BOOST_USE_WINAPI_VERSION to Win7 does not flip it — the capability is
    detected at build time from WaitOnAddress availability, not gated on the
    target-version macro.)
  2. POSIX semaphore (sem_based_event) on platforms with pthreads but no native
    atomic wait/notify (e.g. some macOS configs). sem_post has no
    "skip if already posted" fast path, so this path is not affected.
  3. winapi_based_event only on Windows without a native atomic wait/notify
    (pre-WaitOnAddress). Its set_signalled() carries the same fast-path
    defect (see the note at the end).

x86 additionally provides the specific StoreLoad timing window that makes the race
easy to hit; weakly-ordered architectures would be even more exposed. The original
field failures were on x86-64 Linux.

Minimal reproduction

An asynchronous_sink flushed from one thread via core::flush() while another
logs, looped. A single run rarely trips it; under an aggressive stress config
(many bursty producers + several concurrent flushers, sub-second iterations):

  • Linux, atomic_based_event: a stock 1.89.0 build reliably stalls within a
    couple thousand iterations (observed at iterations 1121 and 1537). gdb shows the
    feeder parked in atomic_based_event::wait() with m_state == 0 while
    m_interruption_requested == 1 and a flusher blocked on m_BlockCond. With the
    fix, the identical loop ran 10000 times with zero stalls.
  • Windows 11 x64, winapi_based_event (forced path, since modern Windows
    otherwise selects atomic_based_event): stalls at iteration 117. cdb shows the
    same signature — feeder parked in winapi_based_event::wait() /
    WaitOnAddress with m_state == 0, kernel handle NULL (native sub-path),
    while m_interruption_requested == 1, and a flusher in
    asynchronous_sink::flush() on m_BlockCond. With the fix, 10000 iterations
    ran with zero stalls.

Both captures show the two livelock-ruling-out mechanisms at work (the core's
exclusive lock held across the flush, and consume() back-pressuring producers),
so the queue cannot grow — the only reason the flush never returns is the feeder
never waking.

(Repro sources and captured gdb/cdb evidence can be attached to the PR.)

Fix

Restore the pre-1.78 semantics — make set_signalled() an unconditional
read-modify-write and notify whenever it transitions the state, using acq_rel
to match wait():

BOOST_LOG_API void atomic_based_event::set_signalled()
{
    if (m_state.exchange(1u, boost::memory_order_acq_rel) == 0u)
        m_state.notify_one();
}

All synchronization funnels through the single variable m_state, so
release/acquire on it is sufficient (a seq_cst total order across variables is
not needed). PR to follow.

winapi_based_event::set_signalled() (the legacy-Windows class) carries the
identical "already signalled → fence only, skip the wake" fast path, and both
of its sub-paths share this defect:

  • its native-wait sub-path (m_event == NULL, when boost::atomic reports a
    native wait/notify) is the direct analogue of the atomic_based_event bug —
    this is the sub-path reproduced live on Windows;
  • its kernel-event sub-path (m_event != NULL) is not saved by the
    auto-reset event's sticky SetEvent, because the fast path skips SetEvent
    altogether — an interrupt's wake can be collapsed into a prior enqueue's
    SetEvent that the feeder already consumed and auto-reset.

The same unconditional-RMW fix is applied to both atomic_based_event and
winapi_based_event in the PR.

Tooling and review

Claude Code (Anthropic) was used during this investigation — to help reproduce
the stall, reason about the memory model, and draft this report. I reviewed all
of it thoroughly: I am a software engineer with 15+ years of C++ experience, I
have independently verified the root-cause analysis, the memory-ordering
argument, the disassembly, and the reproduction on both Linux and Windows, and I
stand behind the analysis as my own.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions