From 8afeaf6c929fb768be18dd516c6414b989a01384 Mon Sep 17 00:00:00 2001 From: acamilo Date: Tue, 22 Sep 2026 14:29:42 +0000 Subject: [PATCH] bus: wait for the teardown the disconnect test asserts caller_disconnect_cleanup_works_before_and_after_consumption failed 37 times in 240 runs under load: the reply raced the router's own teardown. op_reply reports routed:false only once disconnect has marked the call detached, and the router runs that when its connection task reads EOF, while Client::close waits for this client's reader only. The reply could therefore reach a connection that was still closing and be routed. Nothing escaped -- teardown releases those roots -- but the flag was read one step early. The test now settles on the caller's connection being gone before asserting the section 6 sentence, which is the poll the rest of the file already uses. 360 runs after the fix, 0 failures. bus-conformance.md records the mechanism, the counts and the two other intermittent failures seen in the same sweep, which are left to the bus slice. --- .../session-framework/bus-conformance.md | 41 ++++++++++++++++++- .../crates/flybus/tests/sol_review_races.rs | 7 ++++ 2 files changed, 47 insertions(+), 1 deletion(-) diff --git a/docs/design/session-framework/bus-conformance.md b/docs/design/session-framework/bus-conformance.md index cd90df6..68fa08c 100644 --- a/docs/design/session-framework/bus-conformance.md +++ b/docs/design/session-framework/bus-conformance.md @@ -119,7 +119,7 @@ and once over a Unix socket, so `tests/rpc.rs::request_reply_roundtrip` means | Requirement | Status | Code | Test | | --- | --- | --- | --- | | `call-` with increasing serials per connected client; reused or retired ids are rejected, never executed again | conforms: a syntactically valid id advances the watermark even when admission is refused | `router/state.rs::op_call` (`call_watermark`) | `tests/sol_review_races.rs::rejected_call_id_still_advances_monotonic_watermark`, `tests/rpc.rs::raw_call_ids_and_forged_replies` (both) | -| Reconnecting creates a new incarnation rather than reviving old calls | conforms | `router/state.rs::{hello, disconnect}` | `tests/sol_review_races.rs::caller_disconnect_cleanup_works_before_and_after_consumption` | +| Reconnecting creates a new incarnation rather than reviving old calls | conforms | `router/state.rs::{hello, disconnect}` | `tests/sol_review_races.rs::caller_disconnect_cleanup_works_before_and_after_consumption` (its synchronisation was fixed on 2026-09-22; see "A flaky test and what it was measuring") | | An RPC targets one registered service, not a broadcast subject | conforms | `router/state.rs::op_call` | `tests/rpc.rs::request_reply_roundtrip` (both) | | First-dispatch FIFO per caller and service; responses may complete out of order and correlate by callId | conforms | `router/state.rs::{Svc::queue, dispatch_rpc}` | `tests/rpc.rs::fifo_dispatch_and_out_of_order_completion` (both), `tests/conformance_routing.rs::out_of_order_replies_correlate_across_concurrent_callers` (both) | | A service dispatcher can answer status concurrently with a long mutation | conforms | `router/state.rs::dispatch_rpc` (in-flight credits, not one-at-a-time) | `tests/bus_acceptance.rs::a_status_rpc_responds_while_another_handler_is_delayed` (both) | @@ -412,6 +412,45 @@ What the numbers do and do not say: cores against 0.33 to 0.46), because the clients own the copies. A thread that exits between two samples takes its CPU with it, so the router figure is a floor. +## A flaky test and what it was measuring, 2026-09-22 (MEDIA-01) + +`tests/sol_review_races.rs::caller_disconnect_cleanup_works_before_and_after_consumption` +failed intermittently on `main` after the bus slice merged. Reproduced here at +**37 failures in 240 runs** (four parallel loops of 60, debug, on the loaded dev VM), always +on the same line and always the same way: `responder.reply(...)` returned `routed:true` where +the test asserted `false`. + +The mechanism is a synchronisation gap in the test, not a routing defect. +`router/state.rs::op_reply` returns `routed:false` only when `call.detached` is set, and for a +disconnected caller that flag is set by `router/state.rs::disconnect`, which the router runs +when **its** connection task reads EOF. `Client::close` documents what it waits for — "flushes +queued releases, closes the connection and waits until the reader has stopped ... the router +releases what they owned" — which is the client side only. So after `close()` returns, the +router may not have torn the caller's connection down yet, and a reply that reaches it first is +routed to a connection that is already closing. Nothing escapes: `disconnect` then releases +that connection's roots along with the queued result, which is why the test's own later +`settle` calls always passed. Only the `routed` flag, read one step too early, was wrong. + +The fix is in the test: it now waits for the teardown it is talking about +(`e.settle("caller-a disconnected", |s| s.connections == 1)`) before asserting the +reply-to-a-detached-call sentence of section 6. That is the same bounded +poll-until-the-router-settles the rest of the file already uses for router-side consequences; +no sleep, no timing constant, and the assertion now has the precondition its contract sentence +names. **360 runs after the fix, 0 failures** (240 debug, 120 release). + +Two other intermittent failures were seen in the same sweep and are **not** fixed here, since +they belong to the bus slice rather than to this one: + +- `tests/example_demo.rs::the_example_shows_a_counter_rpc_an_observer_and_a_held_frame`, + 2 failures in 40 standalone runs plus 1 in 12 full-suite runs. It prints + "while the frame is held: 1 artifact(s), 2 root(s)" instead of 1 root: the producer's hold + release is queued on the control lane and had not been applied when the example read the + counts. The same shape of gap, in the guide deliverable's printed output. +- `tests/integration.rs::unix_socket::session_over_one_router`, 1 failure in 12 full-suite + runs and 0 in 40 standalone runs, at the assertion that the deliberately slow consumer + skipped snapshots. Under load it kept up, so the assertion is a timing claim about the + machine. + ## Contradictions Two, both inside bus-v1, both minor, neither resolved by changing code. Both were referred to diff --git a/services/flysim/crates/flybus/tests/sol_review_races.rs b/services/flysim/crates/flybus/tests/sol_review_races.rs index 5b93401..9d26b1b 100644 --- a/services/flysim/crates/flybus/tests/sol_review_races.rs +++ b/services/flysim/crates/flybus/tests/sol_review_races.rs @@ -714,6 +714,13 @@ async fn caller_disconnect_cleanup_works_before_and_after_consumption() { .await; caller.close().await; drop(pending); + // `Client::close` waits for this client to stop; the router marks the call detached when + // *it* observes the disconnect, in its own connection task. Asserting the reply routing + // before that is a race: under load the reply reaches the router first and is routed to a + // connection that is already closing. Nothing escapes -- teardown releases those roots -- + // but `routed` is then true. The contract sentence is about a reply to an already detached + // call, so the test waits for the teardown it is talking about. + e.settle("caller-a disconnected", |s| s.connections == 1).await; assert!(!responder.reply(obj(json!({})), &[]).await.unwrap()); drop(responder); e.settle("retained responder retired", |s| {