IPC stability bugs

Bug 85

Disconnect test fails when the server thread starts late

Status
Open
Symptom
Timeout; worst effect seen: test failure only
Where seen
Bitcoin Core functional tests
Trigger
A client disconnects abruptly, for example because it is killed during a call
First reported
2026-03-12 (first report)
Fixed
Not yet

Summary

The interface_ipc.py test "disconnect during BlockTemplate.waitNext" disconnects a fixed 0.1 s after the server has queued the waitNext request and then expects the server to log "canceled while executing". When the worker thread starts late, which is common under sanitizers on a loaded CI runner, the server instead cancels the request before it runs and logs "canceled before it could be executed". The test then fails waiting for a line that will never appear. The defect is in test code and does not affect users; the server behaves correctly. No fix yet.

What happened

Root cause

run_unclean_disconnect_test in test/functional/interface_ipc.py sends template.waitNext(...), waits for the node to log "IPC server post request" (written on the event loop thread when the request is handed to a worker) plus asyncio.sleep(0.1), drops the promise and closes the connection. It then expects "IPC server: socket disconnected" and "canceled while executing", and later "interrupted (canceled)".

In PassField (include/mp/type-context.h), "canceled while executing" is logged by the m_on_cancel callback, which the worker installs in its first sync() block on the event loop. If the event loop processes the disconnect before that block runs, the block sees the request already cancelled, the worker logs "canceled before it could be executed", and the method never runs, so neither expected message appears. The test assumes 0.1 s is always enough for the worker to be scheduled, which TSan and ASan builds on a runner with dozens of nodes do not guarantee: in the 2026-03-12 log, earlier requests took 6 to 134 ms from "post request" to "executing request".

The expectation was added by 8fe91f37194e ("test: Updates needed after bitcoin-core/libmultiprocess#240"), merged with the subtree update bitcoin#34422, when mp#240 introduced request cancellation. It surfaced within days of mp#253's workflow running the test hundreds of times per job.

Fix

No fix yet; the test is unchanged on Bitcoin Core master. Two approaches were identified. Sjors proposed matching "canceled " (either message) and dropping the "interrupted (canceled)" check, which would remove the race. Waiting for the server's "executing request" line before disconnecting would also remove it, and would keep the test on the path it means to cover.

mp#263 ("ci: bump timeout factor to 40") raised the CI timeout factor, saying it "should prevent false positives like" the mp#256 failure. It could not have: a longer timeout only waits longer for a line that is never written in this case. The failures stopped after 2026-03-26. Most likely this is because mp#264 ("ci: reduce nproc multipliers", merged that day) cut the runs per job from 200-300 to 20-25 and parallelism from 10x to 2x nproc, lowering both the load and the number of attempts, but this is not confirmed.

Next steps

Timeline

Lessons

What would have prevented this bug, found it sooner, or made it easier to debug. The patterns page groups these lessons across all bugs.

Pattern Test timing, and tests that cannot fail: A test that assumes timing

  • Prevented by a design rule, a review checklist item
  • Earliest detector a stress test (did not exist then)
  • Diagnosis moderate
  • Fix design easy
  • Debugging aids logging, CI artifacts
  • Rust no

Would Rust have prevented it? No. A test that assumes 0.1 s is enough for a worker to be scheduled is a timing assumption in test logic; no language rule bears on it. More on Rust

Could it have been prevented?

Yes. The test waits for the server's "post request" log line, then sleeps a fixed 0.1 s and disconnects, expecting the disconnect to land while the method is running. The server logs a distinct line, "executing request", at the moment the test needs to be past; waiting for that line instead of sleeping is the rule ("wait for the event that proves the state, never for a duration"), and the test already used that style for its other two synchronization points. A review checklist item that treats any sleep in a functional test as a question to answer would have flagged the line in bitcoin#34422; the alternative outcome ("canceled before it could be executed") was a documented branch of the same code the test was written against.

Could it have been found sooner?

Only by running the test many times under a sanitizer, which is what found it: the mp#253 workflow that builds Bitcoin Core against the library and repeats the IPC tests hundreds of times per job hit it nine days after the test merged. Bitcoin Core's own CI runs the test once per job and never reported it. A plain review of the wait-then-sleep pattern would have been cheaper still.

What made it hard to debug?

The failure message names a log line that is absent, not a wrong one, and every sighting was under TSan or ASan on a loaded runner, so it looked like slowness. The first sighting's full log holds the diagnosis in three timestamps (post .523, disconnected .574, executing .575), and Sjors's proposed change the next day shows he had read it; but the change was not applied, the later sightings were read as a timeout-factor problem and led to mp#263, whose larger factor waits longer for a line that will never be written, and two of the runs also carried the real getParams use-after-free on the same early-cancel timing, so test defect and server defect were tangled in the same logs. The failures stopped when mp#264 cut the CI load, which hid rather than fixed them; the test is unchanged on master. What would have helped is the habit of asking, on an "expected message not found" failure, which other message the code would log in its place.

Lesson

A test that sleeps to reach a state is asserting a scheduling guarantee the system does not make; wait for the observable event instead, and when a test fails on a missing log line, look for the line the code logged in its place before adjusting timeouts.

Notes

Classification

The survey's classification of this bug. The explorer charts these fields across all bugs; the method page explains them.

Field Value
Symptom timeout
Worst effect observed test-failure-only
Seen in functional-test
Scope test-code
Trigger Client disconnects abruptly (client-unclean-disconnect)
Phase steady-state
Side client
Component test-harness
Root cause kind assumption-violated
Fix kind none
Detection ci-intermittent
Needs a peer that is not libmultiprocess C++ yes
Needed a sanitizer to see yes
Confidence medium