diff --git a/crates/fbuild-cli/src/daemon_client.rs b/crates/fbuild-cli/src/daemon_client.rs index 9d32d9817..f1a316ccc 100644 --- a/crates/fbuild-cli/src/daemon_client.rs +++ b/crates/fbuild-cli/src/daemon_client.rs @@ -10,6 +10,7 @@ use serde::Serialize; mod identity; mod restart_diag; +mod startup_log; mod types; pub use identity::warn_if_daemon_identity_mismatch; pub use types::*; @@ -1140,6 +1141,8 @@ async fn start_daemon(client: &DaemonClient) -> fbuild_core::Result> // Retry daemon spawn up to 3 times with exponential backoff // (matches Python behavior: [0.0s, 0.5s, 2.0s] delays between attempts) let backoff_delays = [0.0, 0.5, 2.0]; + // Daemon-log lines from here on explain a failure below (#1627). + let spawn_started = startup_log::log_timestamp(std::time::SystemTime::now()); for (attempt, &delay) in backoff_delays.iter().enumerate() { if attempt > 0 { @@ -1216,9 +1219,10 @@ async fn start_daemon(client: &DaemonClient) -> fbuild_core::Result> version (FastLED/fbuild#1009), so a version-mismatched daemon listens on a different \ port than this CLI polls and can never be reached. When running a locally-built CLI, \ build the daemon too (`soldr cargo build -p fbuild-daemon`) so a sibling binary exists \ - instead of resolving `fbuild-daemon` from PATH.", + instead of resolving `fbuild-daemon` from PATH.{}", runtime_diagnostic(), - wedged_daemon_hint() + wedged_daemon_hint(), + startup_log::startup_problems_note(&spawn_started) ))) } diff --git a/crates/fbuild-cli/src/daemon_client/README.md b/crates/fbuild-cli/src/daemon_client/README.md index 0fe28fb4f..09f0dad08 100644 --- a/crates/fbuild-cli/src/daemon_client/README.md +++ b/crates/fbuild-cli/src/daemon_client/README.md @@ -4,4 +4,5 @@ HTTP client + deserialization types the CLI uses to talk to the fbuild daemon. - `types.rs` — request/response structs that mirror the daemon's JSON schemas (`crates/fbuild-daemon/src/models.rs`). Keep field-for-field compatible so deserialization stays forgiving via `#[serde(default)]`. - `restart_diag.rs` — evidence strings for the same-version daemon restart decision: which daemon image answered `/health`, which sibling binary the CLI compared it to, and a post-respawn check that flags a second launcher serving the port (FastLED/fbuild#1476). +- `startup_log.rs` — quotes the WARN/ERROR lines the daemon wrote to `daemon.log` during the CLI's spawn attempts into the "did not become healthy" error, so a startup failure names its cause (FastLED/fbuild#1627). - Sibling `mod.rs` (one level up at `daemon_client.rs`) — HTTP transport, daemon lifecycle, retry logic. diff --git a/crates/fbuild-cli/src/daemon_client/startup_log.rs b/crates/fbuild-cli/src/daemon_client/startup_log.rs new file mode 100644 index 000000000..5c41cb4bd --- /dev/null +++ b/crates/fbuild-cli/src/daemon_client/startup_log.rs @@ -0,0 +1,134 @@ +//! Why a spawned daemon never became healthy, read back from its own log. +//! +//! The daemon records the startup failure (cache-root ownership busy, a bind +//! collision, a panic) in `daemon.log`, but the CLI used to report only "did +//! not become healthy after 3 spawn attempts", so a CI flake left nothing to +//! diagnose (FastLED/fbuild#1627). This module pulls the warnings and errors +//! the daemon logged during this CLI's spawn attempts into that error. + +/// How many problem lines to quote; enough for one line per spawn attempt +/// plus a retry warning or two, without burying the error. +const MAX_LINES: usize = 8; + +/// UTC RFC 3339 timestamp with microseconds, the format `tracing` prefixes +/// each `daemon.log` line with, so log timestamps compare as strings. +pub(super) fn log_timestamp(time: std::time::SystemTime) -> String { + let micros = time + .duration_since(std::time::UNIX_EPOCH) + .unwrap_or_default() + .as_micros(); + let secs = (micros / 1_000_000) as i64; + let (days, rem) = (secs.div_euclid(86_400), secs.rem_euclid(86_400)); + // Civil-from-days (Howard Hinnant), valid for the proleptic Gregorian calendar. + let z = days + 719_468; + let era = z.div_euclid(146_097); + let doe = z.rem_euclid(146_097); + let yoe = (doe - doe / 1460 + doe / 36_524 - doe / 146_096) / 365; + let doy = doe - (365 * yoe + yoe / 4 - yoe / 100); + let mp = (5 * doy + 2) / 153; + let day = doy - (153 * mp + 2) / 5 + 1; + let month = if mp < 10 { mp + 3 } else { mp - 9 }; + let year = yoe + era * 400 + i64::from(month <= 2); + format!( + "{year:04}-{month:02}-{day:02}T{:02}:{:02}:{:02}.{:06}Z", + rem / 3600, + rem % 3600 / 60, + rem % 60, + micros % 1_000_000 + ) +} + +/// WARN/ERROR lines logged at or after `since` (a [`log_timestamp`]), with +/// ANSI colour stripped, most recent last. +pub(super) fn startup_problems(log: &str, since: &str) -> Vec { + let mut lines: Vec = log + .lines() + .map(strip_ansi) + .filter(|line| line.get(..since.len()).is_some_and(|stamp| stamp >= since)) + .filter(|line| line.contains(" WARN ") || line.contains(" ERROR ")) + .collect(); + let excess = lines.len().saturating_sub(MAX_LINES); + lines.drain(..excess); + lines +} + +/// The block appended to the "did not become healthy" error, or empty when +/// the daemon logged nothing useful. +pub(super) fn startup_problems_note(since: &str) -> String { + let path = fbuild_paths::get_daemon_log_file(); + let Ok(log) = std::fs::read_to_string(&path) else { + return String::new(); + }; + let problems = startup_problems(&log, since); + if problems.is_empty() { + return String::new(); + } + format!( + "\n\nThe daemon logged these problems during the spawn attempts ({}):\n {}", + path.display(), + problems.join("\n ") + ) +} + +fn strip_ansi(line: &str) -> String { + let mut out = String::with_capacity(line.len()); + let mut chars = line.chars(); + while let Some(c) = chars.next() { + if c == '\u{1b}' { + // CSI: ESC '[' params... final byte in '@'..='~'. + if chars.next() == Some('[') { + for c in chars.by_ref() { + if ('@'..='~').contains(&c) { + break; + } + } + } + } else { + out.push(c); + } + } + out +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn timestamp_matches_tracing_format() { + let t = std::time::UNIX_EPOCH + std::time::Duration::from_micros(1_792_903_040_071_970); + assert_eq!(log_timestamp(t), "2026-10-25T04:37:20.071970Z"); + assert_eq!( + log_timestamp(std::time::UNIX_EPOCH), + "1970-01-01T00:00:00.000000Z" + ); + } + + #[test] + fn keeps_only_recent_warnings_and_errors_without_colour() { + let log = "\ +\u{1b}[2m2026-10-25T04:00:00.000000Z\u{1b}[0m \u{1b}[33m WARN\u{1b}[0m old run: bind failed\n\ +\u{1b}[2m2026-10-25T05:00:00.500000Z\u{1b}[0m \u{1b}[32m INFO\u{1b}[0m fbuild daemon starting on port 11393\n\ +\u{1b}[2m2026-10-25T05:00:01.000000Z\u{1b}[0m \u{1b}[33m WARN\u{1b}[0m bind to 127.0.0.1:11393 failed (Address in use)\n\ +\u{1b}[2m2026-10-25T05:00:02.000000Z\u{1b}[0m \u{1b}[31mERROR\u{1b}[0m another fbuild-daemon owns the cache root\n\ +not a log line\n"; + let problems = startup_problems(log, "2026-10-25T05:00:00.000000Z"); + assert_eq!( + problems, + [ + "2026-10-25T05:00:01.000000Z WARN bind to 127.0.0.1:11393 failed (Address in use)", + "2026-10-25T05:00:02.000000Z ERROR another fbuild-daemon owns the cache root", + ] + ); + } + + #[test] + fn quotes_at_most_the_last_few_lines() { + let log: String = (0..20) + .map(|i| format!("2026-10-25T05:00:{i:02}.000000Z WARN attempt {i}\n")) + .collect(); + let problems = startup_problems(&log, "2026-10-25T05:00:00.000000Z"); + assert_eq!(problems.len(), MAX_LINES); + assert!(problems.last().unwrap().ends_with("attempt 19")); + } +}