From d68940f57c18e5b1fbd4f791580f030e0216e324 Mon Sep 17 00:00:00 2001 From: EJ Campbell Date: Sun, 25 Oct 2026 19:07:14 -0700 Subject: [PATCH] fc-agent times the container-state read and bounds the reap after a timeout Before the restore hook runs, fc-agent reads whether fcvm-container runs (`podman inspect`) with a 10 s budget, and a read that runs out fails the restore closed. Two clones of a 128 GiB www snapshot restored at once on a 72-CPU host held the run queue at 82 to 123, and 4 of the 5 second and third clones failed there; clones restored one at a time passed. Nothing recorded how long the read takes, so neither the healthy distribution nor how far a starved read is from the budget was known. The read is now timed: when podman returns, a log line gives its exit code and elapsed_ms, and a failure carries elapsed_ms in its error. A bounded command that runs out (run_bounded, which also runs the hook) now says it hit its budget, how long the reap after the kill took (or that the wait failed, or that the pid was not reaped), fc-agent's vitals line, and the guest's blocked threads and per-CPU ticks with steal, which tell a host that is not running the vCPUs from a busy guest. The vitals are read off the tokio worker. The reap has its own 5 s bound: a child stuck in uninterruptible sleep does not die on SIGKILL, and the unbounded wait would have left the restore hanging with ingress gated instead of failing closed. Tested: make test-agent-unit (274 passed); make clippy; cargo check -p fc-agent for both musl targets. Red: with the old one-line timeout error, a_hook_past_its_budget_is_killed fails on its new assertions; a_timeout_names_a_child_that_was_not_reaped pins the other two messages. --- fc-agent/src/restore.rs | 2 +- fc-agent/src/snapshot_network.rs | 106 +++++++++++++++++++++++++++++-- fc-agent/src/vitals.rs | 14 ++++ 3 files changed, 116 insertions(+), 6 deletions(-) diff --git a/fc-agent/src/restore.rs b/fc-agent/src/restore.rs index 3ea6a254b..3e763814b 100644 --- a/fc-agent/src/restore.rs +++ b/fc-agent/src/restore.rs @@ -265,7 +265,7 @@ fn round_timings(value: &mut serde_json::Value) { } } -fn elapsed_ms(since: std::time::Instant) -> f64 { +pub(crate) fn elapsed_ms(since: std::time::Instant) -> f64 { since.elapsed().as_secs_f64() * 1000.0 } diff --git a/fc-agent/src/snapshot_network.rs b/fc-agent/src/snapshot_network.rs index c8b945fcf..de0c317f5 100644 --- a/fc-agent/src/snapshot_network.rs +++ b/fc-agent/src/snapshot_network.rs @@ -1902,6 +1902,12 @@ struct BoundedOutput { stderr: Vec, } +/// How long `run_bounded` waits for a child it killed at its budget to be reaped. +/// A SIGKILLed process is normally reaped in milliseconds (the timeout test logs +/// the measured reap); one in uninterruptible sleep dies only when its I/O +/// completes, and past this bound the restore fails closed rather than wait. +const RUN_BOUNDED_REAP_BUDGET: std::time::Duration = std::time::Duration::from_secs(5); + /// Run `argv` with a budget. The child is killed when the budget ends (and when /// this future is dropped), and at most `RESTORE_HOOK_OUTPUT_LIMIT` bytes of each /// stream are kept. @@ -1949,14 +1955,60 @@ async fn run_bounded(argv: &[String], budget: std::time::Duration) -> Result result, Err(_) => { // The future above is dropped by the timeout; kill the child and reap it, - // so nothing it spawned keeps running under the clone's name. + // so nothing it spawned keeps running under the clone's name. The reap has + // its own bound: a child stuck in uninterruptible sleep does not die on + // SIGKILL, and an unbounded wait would leave the restore hanging with + // ingress gated instead of failing closed. + let pid = child.id(); let _ = child.start_kill(); - let _ = child.wait().await; - bail!("did not finish within {budget:?}") + let reap_started = std::time::Instant::now(); + let reap = match tokio::time::timeout(RUN_BOUNDED_REAP_BUDGET, child.wait()).await { + Ok(Ok(_)) => Reap::Reaped(crate::restore::elapsed_ms(reap_started)), + Ok(Err(error)) => Reap::WaitFailed(error), + Err(_) => Reap::NotReaped, + }; + let vitals = tokio::task::spawn_blocking(|| { + format!( + "{}; {}", + crate::vitals::sample_line(), + crate::vitals::scheduling_line() + ) + }) + .await + .unwrap_or_else(|error| format!("vitals unavailable: {error}")); + bail!("{}", timeout_message(budget, pid, reap, &vitals)) } } } +/// What happened to a child `run_bounded` killed at its budget. +enum Reap { + /// Reaped this many milliseconds after the kill. + Reaped(f64), + /// Waiting for it failed; whether it still runs is not known. + WaitFailed(std::io::Error), + /// Not reaped within RUN_BOUNDED_REAP_BUDGET. + NotReaped, +} + +/// The error of a `run_bounded` command that ran out of `budget`. +fn timeout_message( + budget: std::time::Duration, + pid: Option, + reap: Reap, + vitals: &str, +) -> String { + let pid = pid.map_or_else(|| "?".to_string(), |pid| pid.to_string()); + let reaped = match reap { + Reap::Reaped(ms) => format!("killed and reaped elapsed_ms={ms:.0} later"), + Reap::WaitFailed(error) => format!("killed pid {pid}, and waiting for it failed: {error}"), + Reap::NotReaped => { + format!("pid {pid} was not reaped {RUN_BOUNDED_REAP_BUDGET:?} after SIGKILL") + } + }; + format!("did not finish within {budget:?}; {reaped}; {vitals}") +} + /// The plan's hook, run inside the container through `podman exec`, as the /// container's user, under the container's own `timeout` so the command ends /// there when the budget does, not only its client here. @@ -2042,9 +2094,25 @@ impl ContainerRestoreHook { impl RestoreHook for ContainerRestoreHook { async fn run(&self) -> Result<()> { + // Timed either way: a read that ran out says how long it waited, and one that + // finished gives the healthy distribution to compare a starved one against. + let inspect_started = std::time::Instant::now(); let inspect = run_bounded(&Self::inspect_argv(), HOOK_INSPECT_BUDGET) .await - .context("reading fcvm-container's state before the restore hook")?; + .with_context(|| { + format!( + "reading fcvm-container's state before the restore hook (elapsed_ms={:.0})", + crate::restore::elapsed_ms(inspect_started) + ) + })?; + eprintln!( + "[fc-agent] podman inspect before the restore hook returned code={} elapsed_ms={:.0}", + inspect + .status + .code() + .map_or_else(|| "signal".to_string(), |code| code.to_string()), + crate::restore::elapsed_ms(inspect_started) + ); match hook_eligibility(&inspect) { HookEligibility::Run => {} HookEligibility::Skip(reason) => { @@ -3876,7 +3944,16 @@ mod tests { let error = run_bounded(&argv, std::time::Duration::from_millis(300)) .await .expect_err("a 30 s command cannot finish in 300 ms"); - assert!(format!("{error:#}").contains("did not finish"), "{error:#}"); + let text = format!("{error:#}"); + // The error says it hit the budget, how long the reap after the kill took, + // and what the guest looked like, which is what tells a starved restore + // from a slow one. + assert!(text.contains("did not finish within 300ms"), "{text}"); + assert!(text.contains("killed and reaped elapsed_ms="), "{text}"); + assert!( + text.contains("MemAvailable") && text.contains("procs_blocked="), + "the error carries no vitals: {text}" + ); let pid: u32 = std::fs::read_to_string(&pid_file) .unwrap() .trim() @@ -3891,6 +3968,25 @@ mod tests { ); } + /// A killed child that is not reaped, or whose wait fails, is named by its pid, + /// and the restore fails closed rather than waiting on it. + #[test] + fn a_timeout_names_a_child_that_was_not_reaped() { + let budget = std::time::Duration::from_millis(300); + assert_eq!( + timeout_message(budget, Some(1234), Reap::NotReaped, "v"), + "did not finish within 300ms; pid 1234 was not reaped 5s after SIGKILL; v" + ); + let failed = Reap::WaitFailed(std::io::Error::from_raw_os_error(libc::ECHILD)); + let text = timeout_message(budget, None, failed, "v"); + assert!( + text.starts_with( + "did not finish within 300ms; killed pid ?, and waiting for it failed: " + ), + "{text}" + ); + } + /// At most 64 KiB of each stream is kept; the rest is drained so the hook is /// never blocked on a full pipe. #[tokio::test] diff --git a/fc-agent/src/vitals.rs b/fc-agent/src/vitals.rs index 7e7b1dee5..4029fcf53 100644 --- a/fc-agent/src/vitals.rs +++ b/fc-agent/src/vitals.rs @@ -419,6 +419,20 @@ fn cpu_times(stat: &str) -> String { .join(" ") } +/// Scheduling evidence for a failure line: threads in uninterruptible sleep and +/// per-CPU ticks (steal included), which move when the host is not running the +/// vCPUs, where the memory fields of `sample_line` do not. +pub fn scheduling_line() -> String { + match read_proc("/proc/stat") { + Ok(stat) => format!( + "procs_blocked={} {}", + blocked_count(&stat).map_or_else(|| "?".to_string(), |count| count.to_string()), + cpu_times(&stat) + ), + Err(error) => format!("stat-unavailable({error})"), + } +} + /// Whether a failed read under /proc means the process or thread exited since /// it was listed, which is not a failed read. Any other failure is counted, so /// `unreadable=0` cannot stand over threads that were left out.