Fix idle auto-suspend silently disabled by guest stderr warnings

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/<name>/`. 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), `<name>_port` files (one per declared `[auto_forwards.<name>]`, holding the auto-allocated host port for the VM's lifetime).
+Instance state lives in `instances/<name>/`. 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), `<name>_port` files (one per declared `[auto_forwards.<name>]`, 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).

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() {

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<String> {
+) -> anyhow::Result<std::process::Output> {
     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<String> {
+    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<String> {
+    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,

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]

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;