From a14461a63f906d207b01999d5435b3fdfe8872f1 Mon Sep 17 00:00:00 2001 From: zackees Date: Fri, 17 Apr 2026 08:39:50 -0700 Subject: [PATCH] fix(daemon): surface self-eviction blocker in logs (#51) Previously the self-eviction loop logged idle/busy transitions only at debug level, so users who saw `fbuild-daemon.exe` staying resident had no visibility into whether self-eviction was ticking or what was keeping it alive. Add `DaemonContext::busy_reason()` returning a human-readable blocker (operation in progress, N open serial sessions, N pending attaches) and promote idle-countdown + blocker messages to info level, with a 60s periodic reminder while a blocker persists. Co-Authored-By: Claude Opus 4.7 (1M context) --- crates/fbuild-daemon/src/context.rs | 94 ++++++++++++++++++++++++++++- crates/fbuild-daemon/src/main.rs | 59 +++++++++++++----- 2 files changed, 137 insertions(+), 16 deletions(-) diff --git a/crates/fbuild-daemon/src/context.rs b/crates/fbuild-daemon/src/context.rs index 662f0c0d2..70c6da2aa 100644 --- a/crates/fbuild-daemon/src/context.rs +++ b/crates/fbuild-daemon/src/context.rs @@ -174,6 +174,17 @@ impl DaemonContext { /// we self-evict during that window the client sees a forcibly-closed /// WebSocket and the autoresearch lifecycle breaks. pub fn is_empty(&self) -> bool { + self.busy_reason().is_none() + } + + /// Human-readable description of what is keeping the daemon alive, or + /// `None` if the daemon is idle and eligible for self-eviction. + /// + /// Surfaces the specific blocker (operation in progress, open serial + /// sessions, pending serial attaches) so the self-eviction loop can log + /// it and users can see why the daemon isn't shutting down. See issue + /// FastLED/fbuild#51. + pub fn busy_reason(&self) -> Option { let op_running = self .operation_in_progress .load(std::sync::atomic::Ordering::Relaxed); @@ -181,7 +192,31 @@ impl DaemonContext { let pending_attaches = self .pending_serial_attaches .load(std::sync::atomic::Ordering::Relaxed); - !op_running && serial_session_count == 0 && pending_attaches == 0 + + let mut reasons: Vec = Vec::new(); + if op_running { + reasons.push("build/deploy operation in progress".to_string()); + } + if serial_session_count > 0 { + reasons.push(format!( + "{} open serial session{}", + serial_session_count, + if serial_session_count == 1 { "" } else { "s" } + )); + } + if pending_attaches > 0 { + reasons.push(format!( + "{} pending serial attach{}", + pending_attaches, + if pending_attaches == 1 { "" } else { "es" } + )); + } + + if reasons.is_empty() { + None + } else { + Some(reasons.join(", ")) + } } /// How long since the daemon started. @@ -254,6 +289,63 @@ mod tests { assert!(!Arc::ptr_eq(&lock1, &lock2)); } + /// `busy_reason()` returns `None` for a fresh context (no ops, no serial + /// sessions, no pending attaches) and `is_empty()` is the negation. + /// Regression guard for FastLED/fbuild#51: a fresh daemon must be + /// immediately eligible for self-eviction. + #[test] + fn busy_reason_none_on_fresh_context() { + let ctx = make_ctx(); + assert_eq!(ctx.busy_reason(), None); + assert!(ctx.is_empty()); + } + + /// An in-progress operation is the primary blocker the self-eviction + /// loop must surface so users can see why the daemon isn't shutting down. + #[test] + fn busy_reason_reports_operation_in_progress() { + let ctx = make_ctx(); + ctx.operation_in_progress.store(true, Ordering::Relaxed); + let reason = ctx.busy_reason().expect("expected a busy reason"); + assert!( + reason.contains("operation in progress"), + "reason should mention the in-progress operation, got: {}", + reason + ); + assert!(!ctx.is_empty()); + } + + /// A pending serial attach (WebSocket client mid-handshake) must keep + /// the daemon alive AND be surfaced in `busy_reason()` so it's visible + /// in logs if the client gets stuck. See FastLED/fbuild#51. + #[test] + fn busy_reason_reports_pending_serial_attach() { + let ctx = make_ctx(); + ctx.pending_serial_attaches.fetch_add(1, Ordering::Relaxed); + let reason = ctx.busy_reason().expect("expected a busy reason"); + assert!( + reason.contains("pending serial attach"), + "reason should mention the pending attach, got: {}", + reason + ); + } + + /// Multiple concurrent blockers should all appear in the report so the + /// self-eviction log line describes the full picture. + #[test] + fn busy_reason_joins_multiple_blockers() { + let ctx = make_ctx(); + ctx.operation_in_progress.store(true, Ordering::Relaxed); + ctx.pending_serial_attaches.fetch_add(2, Ordering::Relaxed); + let reason = ctx.busy_reason().expect("expected a busy reason"); + assert!( + reason.contains("operation in progress") + && reason.contains("2 pending serial attaches"), + "reason should join both blockers, got: {}", + reason + ); + } + /// Issue A follow-up: a streaming serial monitor must keep /// `idle_duration()` near zero by calling `touch_activity()` on every /// inbound line. Verify the contract: stale -> touch -> fresh. diff --git a/crates/fbuild-daemon/src/main.rs b/crates/fbuild-daemon/src/main.rs index 85fdabd32..7d318911b 100644 --- a/crates/fbuild-daemon/src/main.rs +++ b/crates/fbuild-daemon/src/main.rs @@ -134,30 +134,59 @@ async fn main() { tokio::spawn(async move { let mut daemon_empty_since: Option = None; let mut last_lock_cleanup = std::time::Instant::now(); + // Periodic reminder of why the daemon is staying alive, so + // users can see the blocker rather than thinking self-eviction + // is broken. See FastLED/fbuild#51. + let busy_report_interval = std::time::Duration::from_secs(60); + let mut last_busy_report: Option = None; + let mut last_busy_reason: Option = None; loop { tokio::time::sleep(std::time::Duration::from_secs(1)).await; // --- Self-eviction: 0 ops + 0 serial sessions for SELF_EVICTION_TIMEOUT --- - if ctx.is_empty() { - if daemon_empty_since.is_none() { - daemon_empty_since = Some(std::time::Instant::now()); - tracing::debug!( - "Daemon is now empty (0 ops, 0 serial sessions), starting eviction timer" - ); - } else if let Some(since) = daemon_empty_since { - if since.elapsed() >= SELF_EVICTION_TIMEOUT { + match ctx.busy_reason() { + None => { + if last_busy_reason.is_some() { + last_busy_reason = None; + last_busy_report = None; + } + if daemon_empty_since.is_none() { + daemon_empty_since = Some(std::time::Instant::now()); tracing::info!( - "Self-eviction triggered: daemon empty for {:.1}s, shutting down", - since.elapsed().as_secs_f64() + "Daemon is idle; self-eviction in {:.0}s unless new work arrives", + SELF_EVICTION_TIMEOUT.as_secs_f64() ); - let _ = ctx.shutdown_tx.send(true); - return; + } else if let Some(since) = daemon_empty_since { + if since.elapsed() >= SELF_EVICTION_TIMEOUT { + tracing::info!( + "Self-eviction triggered: daemon empty for {:.1}s, shutting down", + since.elapsed().as_secs_f64() + ); + let _ = ctx.shutdown_tx.send(true); + return; + } + } + } + Some(reason) => { + if daemon_empty_since.is_some() { + tracing::debug!("Daemon is no longer empty, resetting eviction timer"); + daemon_empty_since = None; + } + // Announce the blocker on transition and then + // periodically repeat the reminder so a stuck + // session is visible in logs without spamming every + // tick. + let reason_changed = last_busy_reason.as_deref() != Some(reason.as_str()); + let due_for_reminder = last_busy_report + .map(|t| t.elapsed() >= busy_report_interval) + .unwrap_or(true); + if reason_changed || due_for_reminder { + tracing::info!("Daemon staying alive: {}", reason); + last_busy_report = Some(std::time::Instant::now()); + last_busy_reason = Some(reason); } } - } else if daemon_empty_since.is_some() { - tracing::debug!("Daemon is no longer empty, resetting eviction timer"); - daemon_empty_since = None; } // --- Idle timeout (12h fallback) ---