diff --git a/AGENTS.md b/AGENTS.md index 2b02a8e..c11c39f 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -161,7 +161,7 @@ Forward-compatibility caveat: serde and Swift's `JSONDecoder` both ignore unknow `~/.local/share/agv/` (XDG-compliant, same on all platforms). Override with `AGV_DATA_DIR`. -Instance state lives in `instances//`. Files common to both backends: `seed.iso`, `id_ed25519`, `id_ed25519.pub`, `config.toml`, `status`, `serial.log`, `provision.log`, `error.log`, `provisioned`, `provision_state`, `idle_watcher.pid`, `forwards.toml` (present when forwards are active; lists each forward's spec, origin, and supervisor PID), `_port` files (one per declared `[auto_forwards.]`, holding the auto-allocated host port for the VM's lifetime). +Instance state lives in `instances//`. Files common to both backends: `seed.iso`, `id_ed25519`, `id_ed25519.pub`, `config.toml`, `status`, `serial.log`, `provision.log`, `error.log`, `provisioned`, `provision_state`, `idle_watcher.pid`, `idle_watcher.log` (the watcher's redirected stderr — probe/idle decisions and suspend attempts; truncated per watcher spawn), `forwards.toml` (present when forwards are active; lists each forward's spec, origin, and supervisor PID), `_port` files (one per declared `[auto_forwards.]`, holding the auto-allocated host port for the VM's lifetime). Backend-specific files: - **QEMU**: `disk.qcow2`, `pid`, `ssh_port`, `qmp.sock`, `efi-vars.fd` (aarch64 only). diff --git a/src/idle_watcher.rs b/src/idle_watcher.rs index 21d8c42..a959111 100644 --- a/src/idle_watcher.rs +++ b/src/idle_watcher.rs @@ -179,14 +179,18 @@ pub async fn run( match probe(&inst, &user).await { Ok((who_count, loadavg)) => match evaluate(who_count, loadavg, load_threshold) { Activity::Active => { - if idle_secs > 0 { - debug!( - vm = vm_name, - who = who_count, - load = loadavg, - "activity detected; resetting idle timer" - ); - } + // Log every active tick, not just when idle_secs > 0. + // The old gate meant a VM that was active from the very + // first probe logged nothing at all — which is exactly + // how a stderr-polluted `who` count silently kept a VM + // "active" forever with no trace of why. + debug!( + vm = vm_name, + who = who_count, + load = loadavg, + idle_secs, + "tick active" + ); idle_secs = 0; } Activity::Idle => { @@ -236,13 +240,18 @@ pub async fn run( /// One probe: SSH in, read `who` and `/proc/loadavg`, return /// `(interactive_session_count, 5-min load average)`. +/// +/// Uses [`ssh::run_cmd_stdout`], not `run_cmd`: both outputs are parsed, +/// so stderr chatter (e.g. a guest `setlocale` warning when the client +/// forwards `LC_*`) must be kept out — otherwise it lands in the `who` +/// result and makes an idle VM look active forever. async fn probe(inst: &Instance, user: &str) -> anyhow::Result<(u32, f32)> { - let who_out = ssh::run_cmd(inst, user, &["who".to_string()]).await?; + let who_out = ssh::run_cmd_stdout(inst, user, &["who".to_string()]).await?; let who_count = who_out .lines() .filter(|l| !l.trim().is_empty()) .count(); - let loadavg_out = ssh::run_cmd( + let loadavg_out = ssh::run_cmd_stdout( inst, user, &["cat".to_string(), "/proc/loadavg".to_string()], @@ -301,14 +310,31 @@ pub async fn spawn(name: &str, threshold_minutes: u32, load_threshold: f32) { return; } }; + // Redirect the watcher's stdout AND stderr to a per-instance log file so + // its tracing output isn't lost to /dev/null. Both streams are captured + // because `tracing_subscriber::fmt()` writes to stdout by default — a + // stderr-only redirect leaves the log empty. The watcher has no + // user-facing stdout of its own, so this is purely its log. Best-effort: + // fall back to /dev/null if the file can't be opened, never fatal. Re-run + // with `RUST_LOG=agv=debug` to capture the per-tick probe/idle lines. + let (log_out, log_err) = match std::fs::File::create(inst.idle_watcher_log_path()) { + Ok(file) => { + let err = file + .try_clone() + .map_or_else(|_| Stdio::null(), Stdio::from); + (Stdio::from(file), err) + } + Err(_) => (Stdio::null(), Stdio::null()), + }; + let mut cmd = std::process::Command::new(exe); cmd.arg("__idle-watcher") .arg(name) .arg(threshold_minutes.to_string()) .arg(load_threshold.to_string()) .stdin(Stdio::null()) - .stdout(Stdio::null()) - .stderr(Stdio::null()); + .stdout(log_out) + .stderr(log_err); cmd.process_group(0); match cmd.spawn() { diff --git a/src/ssh.rs b/src/ssh.rs index e7fb700..d60d0ef 100644 --- a/src/ssh.rs +++ b/src/ssh.rs @@ -92,16 +92,14 @@ pub async fn session( } } -/// Run a command over SSH, capturing stdout and stderr. -/// -/// Returns the combined output as a string. Fails with context if the -/// command exits non-zero. Use this instead of `session()` when the -/// output should be captured rather than forwarded to the terminal. -pub async fn run_cmd( +/// Spawn `ssh` for a one-shot command and collect its raw `Output` +/// (stdout, stderr, and exit status). Shared by [`run_cmd`] and +/// [`run_cmd_stdout`]; callers decide how to treat the streams. +async fn ssh_output( instance: &Instance, user: &str, command: &[String], -) -> anyhow::Result { +) -> anyhow::Result { let (host, port) = crate::vm::backend::for_instance(instance)? .ssh_endpoint(instance) .await?; @@ -118,19 +116,34 @@ pub async fn run_cmd( cmd.args(command); } - let output = match cmd.output().await { - Ok(o) => o, + match cmd.output().await { + Ok(o) => Ok(o), Err(e) if e.kind() == std::io::ErrorKind::NotFound => { bail!("ssh not found — run 'agv doctor' to check all dependencies"); } - Err(source) => { - return Err(Error::Ssh { - name: instance.name.clone(), - source, - } - .into()); + Err(source) => Err(Error::Ssh { + name: instance.name.clone(), + source, } - }; + .into()), + } +} + +/// Run a command over SSH, capturing stdout and stderr. +/// +/// Returns the combined output as a string. Fails with context if the +/// command exits non-zero. Use this instead of `session()` when the +/// output should be captured rather than forwarded to the terminal. +/// +/// Because it folds stderr into the returned string, this is for +/// display/logging — **not** for parsing a command's output. To parse, +/// use [`run_cmd_stdout`], which keeps stderr out of the result. +pub async fn run_cmd( + instance: &Instance, + user: &str, + command: &[String], +) -> anyhow::Result { + let output = ssh_output(instance, user, command).await?; let combined = { let stdout = String::from_utf8_lossy(&output.stdout); @@ -155,6 +168,33 @@ pub async fn run_cmd( Ok(combined) } +/// Run a command over SSH and return **only stdout** on success. +/// +/// Unlike [`run_cmd`], stderr is never folded into the result — it's used +/// solely for the error message on a non-zero exit. Use this whenever the +/// caller parses the command's output: incidental stderr chatter would +/// otherwise corrupt the parse. +/// +/// The motivating case is the idle watcher's `who` probe. When the host's +/// SSH forwards `LC_*` to a guest that can't set that locale, the guest +/// shell prints a `setlocale` warning to stderr; folded into an otherwise +/// empty `who` stdout, it made `who` look non-empty, so the VM was seen as +/// active and never auto-suspended. +pub async fn run_cmd_stdout( + instance: &Instance, + user: &str, + command: &[String], +) -> anyhow::Result { + let output = ssh_output(instance, user, command).await?; + + if !output.status.success() { + let stderr = String::from_utf8_lossy(&output.stderr); + anyhow::bail!("SSH command exited with {}: {}", output.status, stderr.trim()); + } + + Ok(String::from_utf8_lossy(&output.stdout).into_owned()) +} + /// Copy a file into the VM using scp. pub async fn copy_to( instance: &Instance, diff --git a/src/vm/instance.rs b/src/vm/instance.rs index e6f3fe8..cd4fcb9 100644 --- a/src/vm/instance.rs +++ b/src/vm/instance.rs @@ -258,6 +258,19 @@ impl Instance { self.dir.join("idle_watcher.pid") } + /// Path to the idle-watcher's log file. + /// + /// The watcher is a detached background process, so its tracing output + /// would otherwise be lost. Redirecting its stderr here keeps a record + /// of each probe/idle decision and any suspend attempt — the only way + /// to diagnose "why didn't the VM auto-suspend?" after the fact. + /// Truncated each time a watcher is spawned, so it reflects the current + /// watcher session. + #[must_use] + pub fn idle_watcher_log_path(&self) -> PathBuf { + self.dir.join("idle_watcher.log") + } + /// AVF-only — control socket the agv-avf-runner binds to accept /// JSON-RPC commands from the parent agv process. #[must_use] diff --git a/tests/create_test.rs b/tests/create_test.rs index 97f9dfb..65918dc 100644 --- a/tests/create_test.rs +++ b/tests/create_test.rs @@ -446,6 +446,18 @@ async fn backend_cleanup_removes_residual_qcow2_after_flip() { eprintln!("required tools missing — skipping backend_cleanup_removes_residual_qcow2_after_flip"); return; } + // The test flips the instance config to `backend = "avf"` to simulate a + // migrate-to-avf, then cleans up the residual qcow2. Loading an AVF-backed + // config is refused off macOS ("avf is macOS-only"), and the whole + // flip-then-clean workflow only exists on macOS Apple Silicon anyway, so + // there's nothing to exercise on other platforms. + if !cfg!(target_os = "macos") { + eprintln!( + "AVF-flip cleanup is a macOS-only workflow — skipping \ + backend_cleanup_removes_residual_qcow2_after_flip" + ); + return; + } let data_dir = test_data_dir(); let host_tmp = tempfile::tempdir().unwrap(); @@ -1437,16 +1449,24 @@ idle_load_threshold = 2.0 let report = parse_json("agv create", &create_output.stdout); assert_eq!(report["status"], "running"); - // Watcher probes every 60s; with idle_suspend_minutes=1 the first - // idle probe (≈60s after spawn) will trigger a savevm + QEMU exit. - // 100s gives the suspend RPC and status-file write time to land. - tokio::time::sleep(std::time::Duration::from_secs(100)).await; - - let report = inspect(data_dir.path(), name).await; + // The watcher probes every 60s; with idle_suspend_minutes=1 the first + // idle probe (~60s after spawn) triggers a savevm + QEMU exit. Poll for + // the `suspended` status rather than sleeping a single fixed window — + // that window is fragile on slow or loaded machines, where savevm + // latency or a watcher tick stretched past 2× the probe interval (which + // trips the host-wake heuristic and resets the idle timer) can push the + // suspend past the deadline. A genuine "never suspends" bug still fails + // here, just after a fair wait instead of an arbitrary 100s. + let deadline = std::time::Instant::now() + std::time::Duration::from_secs(240); + let mut report = inspect(data_dir.path(), name).await; + while report["status"].as_str() != Some("suspended") && std::time::Instant::now() < deadline { + tokio::time::sleep(std::time::Duration::from_secs(10)).await; + report = inspect(data_dir.path(), name).await; + } let status = report["status"].as_str().unwrap_or(""); if status != "suspended" { destroy(data_dir.path(), name).await; - panic!("expected VM to auto-suspend, got status={status:?}: {report:?}"); + panic!("expected VM to auto-suspend within 240s, got status={status:?}: {report:?}"); } destroy(data_dir.path(), name).await;