From 2aaf6c05dd9f047bba2dfe63c5fabfa8f37aad2f Mon Sep 17 00:00:00 2001 From: ualtinok <94532+ualtinok@users.noreply.github.com> Date: Tue, 27 Oct 2026 06:12:35 +0100 Subject: [PATCH 1/2] mason: hold the stderr mirror at exit so the slow-writer test proves the stderr fence subc_drain_with_slow_writer_persists_terminal_line read its phase=log_flush_done flushed=false line from module stderr, which in subc mode is an asynchronous best-effort mirror. main returned right after queueing that line and the terminal marker, and nothing waited for the mirror thread, so on a busy runner both lines were lost (merge-queue run 40451058606). The previous commit adds the bounded stderr exit fence. Add a debug-only AFT_TEST_STDERR_EXIT_HOLD hook that parks the mirror worker from the end of the durable flush until the stderr exit fence starts, and set it in the slow-writer test. Without the fence the test now loses both lines every run; with it they are delivered. The test also requires the terminal marker on stderr, not only in the durable file. Co-authored-by: alfonso-aft <289616620+alfonso-aft@users.noreply.github.com> (cherry picked from commit 2904e56ed1b42577f4a11115b12fe0ecaf9355b6) --- crates/aft/src/logging.rs | 10 +++ crates/aft/src/logging/stderr_mirror.rs | 90 ++++++++++++++++++- crates/aft/src/main.rs | 8 ++ .../aft/tests/integration/subc_detach_test.rs | 10 +++ 4 files changed, 117 insertions(+), 1 deletion(-) diff --git a/crates/aft/src/logging.rs b/crates/aft/src/logging.rs index f06a598d86..39faa7be9b 100644 --- a/crates/aft/src/logging.rs +++ b/crates/aft/src/logging.rs @@ -1616,6 +1616,16 @@ pub fn flush_stderr_on_exit(timeout: std::time::Duration) -> bool { .is_none_or(|mirror| mirror.drain_on_exit(timeout)) } +/// Test-only (debug builds): stop the stderr mirror from writing until +/// [`flush_stderr_on_exit`] starts, so the lines logged in between are still +/// queued when the exit fence runs. Without the fence they would be lost. +#[cfg(debug_assertions)] +pub fn hold_stderr_mirror_until_exit_fence() { + if let Some(mirror) = STDERR_MIRROR.get() { + mirror.hold_until_exit_fence(); + } +} + /// Persist the last process-exit line without depending on the async writer. /// Taking its active sink prevents later rotation or reconfiguration from /// moving the marker. Queued diagnostics may be abandoned once their bounded diff --git a/crates/aft/src/logging/stderr_mirror.rs b/crates/aft/src/logging/stderr_mirror.rs index 9f8e7f2e30..2bcfc2be18 100644 --- a/crates/aft/src/logging/stderr_mirror.rs +++ b/crates/aft/src/logging/stderr_mirror.rs @@ -49,10 +49,44 @@ enum Message { Drain(SyncSender), } +/// Test-only (debug builds): parks the worker so that records logged during +/// process exit are still queued when the exit fence starts. That is the +/// state a busy host can leave them in when the process exits right after +/// logging them, and the fence must still deliver them. +#[cfg(debug_assertions)] +#[derive(Default)] +struct ExitHold { + armed: std::sync::Mutex, + released: std::sync::Condvar, +} + +#[cfg(debug_assertions)] +impl ExitHold { + fn arm(&self) { + *self.armed.lock().unwrap_or_else(|e| e.into_inner()) = true; + } + + fn release(&self) { + *self.armed.lock().unwrap_or_else(|e| e.into_inner()) = false; + self.released.notify_all(); + } + + fn wait(&self) { + let armed = self.armed.lock().unwrap_or_else(|e| e.into_inner()); + // Bounded so a hold that is never released cannot keep a test + // process's worker parked forever. + let _ = self + .released + .wait_timeout_while(armed, Duration::from_secs(10), |armed| *armed); + } +} + #[derive(Clone)] pub(super) struct Mirror { tx: Option>, health: Arc, + #[cfg(debug_assertions)] + exit_hold: Arc, } impl Mirror { @@ -63,10 +97,16 @@ impl Mirror { ) -> io::Result<(Self, JoinHandle<()>)> { let (tx, rx) = mpsc::sync_channel(capacity); let worker_health = Arc::clone(&health); + #[cfg(debug_assertions)] + let exit_hold = Arc::new(ExitHold::default()); + #[cfg(debug_assertions)] + let worker_hold = Arc::clone(&exit_hold); let worker = thread::Builder::new() .name("aft-stderr-mirror".into()) .spawn(move || { while let Ok(message) = rx.recv() { + #[cfg(debug_assertions)] + worker_hold.wait(); // No channel or file-sink lock is held during stderr I/O. let result = match &message { Message::Record(bytes) => sink.write_all(bytes), @@ -92,6 +132,8 @@ impl Mirror { Self { tx: Some(tx), health, + #[cfg(debug_assertions)] + exit_hold, }, worker, )) @@ -99,7 +141,12 @@ impl Mirror { pub(super) fn disabled(health: Arc) -> Self { health.start_failures.fetch_add(1, Ordering::Relaxed); - Self { tx: None, health } + Self { + tx: None, + health, + #[cfg(debug_assertions)] + exit_hold: Arc::default(), + } } pub(super) fn record(&self, bytes: &[u8]) { @@ -121,6 +168,8 @@ impl Mirror { // Only process teardown waits for this fence. Ordinary logger flushes stay // nonblocking, including when stderr is full or its sink is wedged. pub(super) fn drain_on_exit(&self, timeout: Duration) -> bool { + #[cfg(debug_assertions)] + self.exit_hold.release(); let Some(tx) = self.tx.as_ref() else { return false; }; @@ -148,6 +197,13 @@ impl Mirror { .unwrap_or(false) } + /// Test-only (debug builds): stop writing records until `drain_on_exit` + /// starts. See [`ExitHold`]. + #[cfg(debug_assertions)] + pub(super) fn hold_until_exit_fence(&self) { + self.exit_hold.arm(); + } + fn enqueue(&self, message: Message) { let Some(tx) = self.tx.as_ref() else { self.health.drop_message(&message); @@ -227,6 +283,36 @@ mod tests { worker.join().unwrap(); } + #[cfg(debug_assertions)] + #[test] + fn exit_hold_keeps_records_queued_until_the_exit_fence_starts() { + let bytes = Arc::new(Mutex::new(Vec::new())); + let (mirror, worker) = Mirror::spawn( + GateWriter { + bytes: Arc::clone(&bytes), + write_gate: None, + flush_gate: None, + }, + 8, + Arc::new(MirrorHealth::default()), + ) + .unwrap(); + mirror.hold_until_exit_fence(); + mirror.record(b"process exit marker\n"); + thread::sleep(Duration::from_millis(50)); + let written_while_held = bytes.lock().unwrap().clone(); + let drained = mirror.drain_on_exit(Duration::from_secs(5)); + drop(mirror); + worker.join().unwrap(); + assert!( + written_while_held.is_empty(), + "held worker wrote {:?}", + String::from_utf8_lossy(&written_while_held) + ); + assert!(drained, "exit fence did not release the held worker"); + assert_eq!(&*bytes.lock().unwrap(), b"process exit marker\n"); + } + #[test] fn full_queue_drops_whole_records_and_flushes_without_waiting() { let bytes = Arc::new(Mutex::new(Vec::new())); @@ -301,6 +387,8 @@ mod tests { let mirror = Mirror { tx: Some(tx), health: Arc::clone(&health), + #[cfg(debug_assertions)] + exit_hold: Arc::default(), }; mirror.record(&vec![b'x'; MAX_RECORD_BYTES + 1]); assert!(matches!(rx.try_recv(), Err(mpsc::TryRecvError::Empty))); diff --git a/crates/aft/src/main.rs b/crates/aft/src/main.rs index d3857d0d42..94816d70ab 100644 --- a/crates/aft/src/main.rs +++ b/crates/aft/src/main.rs @@ -406,6 +406,14 @@ fn main() { aft::subc::exit_elapsed().as_millis() ); let flushed = aft::logging::flush_durable_log(flush_wait); + // AFT_TEST_STDERR_EXIT_HOLD keeps every stderr line from here + // on queued until the stderr exit fence below starts, so a test + // can prove the fence delivers them rather than rely on the + // mirror thread happening to run first. Release builds ignore it. + #[cfg(debug_assertions)] + if std::env::var_os("AFT_TEST_STDERR_EXIT_HOLD").is_some() { + aft::logging::hold_stderr_mirror_until_exit_fence(); + } aft::slog_info!( "subc exit phase=log_flush_done flushed={} elapsed_ms={}", flushed, diff --git a/crates/aft/tests/integration/subc_detach_test.rs b/crates/aft/tests/integration/subc_detach_test.rs index 0bfaa2afa3..324e2e88c3 100644 --- a/crates/aft/tests/integration/subc_detach_test.rs +++ b/crates/aft/tests/integration/subc_detach_test.rs @@ -847,6 +847,11 @@ fn drain_with_live_lsp_servers_and_writer( if writer_delay == "1000" { assert!(log.contains("phase=log_flush_done flushed=false"), "slow writer must exhaust the async flush budget: {}", log_tail(&log)); + // The terminal marker is mirrored to stderr after the queued + // flush; the stderr exit fence must deliver it there as well as + // to the durable file checked below. + assert!(log.contains("subc exit phase=process_exit mode="), + "stderr exit fence must deliver the terminal marker: {}", log_tail(&log)); } // Print phase and LSP summary lines. The bound below uses the LSP // phase's own elapsed value, never the outer process-exit observation. @@ -1185,6 +1190,11 @@ impl ModuleProcess { // A writer this slow cannot acknowledge a flush inside the exit // budget, wherever in its batch delay the request lands. command.env("AFT_TEST_LOG_FLUSH_HOLD_MS", hold); + // Keep the stderr mirror from writing the exit's last lines until + // the stderr exit fence starts, so the stderr assertions prove the + // fence delivers them instead of depending on the mirror thread + // being scheduled before the process exits. + command.env("AFT_TEST_STDERR_EXIT_HOLD", "1"); } if let Some(bin_dir) = bin_dir { // The test supplies its language servers through `bin_dir`. An From 749a0bdd13da30fd36510d9467879236203bc674 Mon Sep 17 00:00:00 2001 From: ualtinok <94532+ualtinok@users.noreply.github.com> Date: Tue, 27 Oct 2026 07:05:28 +0100 Subject: [PATCH 2/2] Search-quality descriptor for the stderr exit-hold test Co-authored-by: alfonso-aft <289616620+alfonso-aft@users.noreply.github.com> --- .../land-stderr-exit-hold-test.json | 12 ++++++++++++ 1 file changed, 12 insertions(+) create mode 100644 benchmarks/aft-search/slice-descriptors/land-stderr-exit-hold-test.json diff --git a/benchmarks/aft-search/slice-descriptors/land-stderr-exit-hold-test.json b/benchmarks/aft-search/slice-descriptors/land-stderr-exit-hold-test.json new file mode 100644 index 0000000000..df864659fb --- /dev/null +++ b/benchmarks/aft-search/slice-descriptors/land-stderr-exit-hold-test.json @@ -0,0 +1,12 @@ +{ + "slice_class": "non_ranking", + "targeted_mechanism": "none", + "kind": "harness", + "fixtures": [ + "harness-goldens" + ], + "slices": [ + "stderr-exit-hold-test" + ], + "note": "Test-only hook (debug builds) that holds the stderr mirror until the exit fence starts, so the slow-writer exit test proves the fence delivers the terminal marker to stderr. No search, ranking or routing code changes." +}