From febeb0d395b3926d9783bbaeef7503376bc72a6c Mon Sep 17 00:00:00 2001 From: iris Date: Sun, 1 Nov 2026 16:13:40 +0100 Subject: [PATCH] hive-c0re logs each container build with build_id, agent, kind, start and finish lines Every output line of a nixos-container operation already reached the journal with its command line. They now also carry the build-log row id, the agent and the kind, and a start and a finish line (status, runtime) bracket them, so the swarm log store can group a build and a board can list builds. --- docs/agent-lifecycle/persistence.md | 8 ++ hive-c0re/src/lifecycle/mod.rs | 132 +++++++++++++++++++++++----- hive-c0re/src/lifecycle/tests.rs | 90 +++++++++++++++++++ 3 files changed, 209 insertions(+), 21 deletions(-) diff --git a/docs/agent-lifecycle/persistence.md b/docs/agent-lifecycle/persistence.md index 46ebcd28..e215c40d 100644 --- a/docs/agent-lifecycle/persistence.md +++ b/docs/agent-lifecycle/persistence.md @@ -210,6 +210,14 @@ Writes are best-effort: `append_stdout` / `append_stderr` / `finish` log a warning on sqlite error and let the build continue. A failed log row never blocks a rebuild. +Each operation also logs to the host journal, target `nixos-container`, and the +swarm log store collects those lines. Every line carries `build_id` (this +table's row id; empty without the store), `agent`, `kind` and `cmdline`. A +`start` line (`event=start`) opens the build, one line follows per line of +output, and a `finish` line (`event=finish`) closes it with `status` (`ok` or +`fail`) and `runtime_secs`. hive-c0re logs a nix warning or error at warn, and a failed +finish too. + A row is open (`finished_at IS NULL`) only while its child runs. At startup `Coordinator::open` closes every row still open as `fail` and appends a line saying hive-c0re stopped: the previous process died mid-build, and diff --git a/hive-c0re/src/lifecycle/mod.rs b/hive-c0re/src/lifecycle/mod.rs index 1855ecbe..f9c4231a 100644 --- a/hive-c0re/src/lifecycle/mod.rs +++ b/hive-c0re/src/lifecycle/mod.rs @@ -766,32 +766,118 @@ fn is_actionable_nix_line(line: &str) -> bool { || trimmed.starts_with("error:") } +/// What every log line of one container operation carries, so the swarm log +/// store can group a build's lines and the builds board can list the builds: +/// `build_id` (the build-log row's id, empty when the store is not installed), +/// `agent` and `kind`. A `start` line opens the build and a `finish` line +/// closes it with its `status` and `runtime_secs`; the output lines between +/// them have no `event`. +#[derive(Clone)] +struct BuildTag { + build_id: String, + agent: String, + kind: String, + cmdline: String, +} + +impl BuildTag { + fn new(log_id: Option, agent: &str, kind: &str, cmdline: &str) -> Self { + Self { + build_id: log_id.map(|id| id.to_string()).unwrap_or_default(), + agent: agent.to_owned(), + kind: kind.to_owned(), + cmdline: cmdline.to_owned(), + } + } + + fn started(&self) { + tracing::info!( + target: "nixos-container", + event = "start", + build_id = %self.build_id, + agent = %self.agent, + kind = %self.kind, + cmdline = %self.cmdline, + "{} started", + self.cmdline + ); + } + + /// One output line; a nix warning or error is logged at warn, the rest at + /// info. + fn line(&self, stream: hive_priv_sock::PrivStream, line: &str) { + let actionable = + matches!(stream, hive_priv_sock::PrivStream::Stderr) && is_actionable_nix_line(line); + if actionable { + tracing::warn!( + target: "nixos-container", + build_id = %self.build_id, + agent = %self.agent, + kind = %self.kind, + cmdline = %self.cmdline, + "{line}" + ); + } else { + tracing::info!( + target: "nixos-container", + build_id = %self.build_id, + agent = %self.agent, + kind = %self.kind, + cmdline = %self.cmdline, + "{line}" + ); + } + } + + fn finished(&self, succeeded: bool, runtime: std::time::Duration) { + let status = if succeeded { "ok" } else { "fail" }; + if succeeded { + tracing::info!( + target: "nixos-container", + event = "finish", + build_id = %self.build_id, + agent = %self.agent, + kind = %self.kind, + status, + runtime_secs = runtime.as_secs(), + cmdline = %self.cmdline, + "{} finished: {status}", + self.cmdline + ); + } else { + tracing::warn!( + target: "nixos-container", + event = "finish", + build_id = %self.build_id, + agent = %self.agent, + kind = %self.kind, + status, + runtime_secs = runtime.as_secs(), + cmdline = %self.cmdline, + "{} finished: {status}", + self.cmdline + ); + } + } +} + /// Build the per-line callback for `create_container_streaming` / /// `update_container_streaming`. Both ops share identical dispatch logic -/// (stdout → info + `append_stdout`, stderr → warn for a nix warning/error -/// and info otherwise + `append_stderr`); this helper avoids duplicating -/// that match body across the two call sites. +/// (log the line through its `BuildTag`, then `append_stdout` or +/// `append_stderr`); this helper avoids duplicating that match body across the +/// two call sites. fn make_log_callback( logs: Option>, log_id: Option, - cmdline: String, + tag: BuildTag, ) -> impl FnMut(hive_priv_sock::PrivStream, &str) { use hive_priv_sock::PrivStream; - move |stream, line| match stream { - PrivStream::Stdout => { - tracing::info!(target: "nixos-container", cmdline = %cmdline, "{line}"); - if let (Some(h), Some(id)) = (&logs, log_id) { - h.append_stdout(id, line); - } - } - PrivStream::Stderr => { - if is_actionable_nix_line(line) { - tracing::warn!(target: "nixos-container", cmdline = %cmdline, "{line}"); - } else { - tracing::info!(target: "nixos-container", cmdline = %cmdline, "{line}"); - } - if let (Some(h), Some(id)) = (&logs, log_id) { - h.append_stderr(id, line); + move |stream, line| { + tag.line(stream, line); + if let (Some(h), Some(id)) = (&logs, log_id) { + match stream { + PrivStream::Stdout => h.append_stdout(id, line), + PrivStream::Stderr => h.append_stderr(id, line), } } } @@ -862,13 +948,16 @@ async fn priv_run_inner( // For long-running ops use the streaming protocol so build_logs // receives lines in real time rather than as a batch at completion. + let tag = BuildTag::new(log_id, name, kind, &cmdline); + tag.started(); + let began = std::time::Instant::now(); let result: Result<()> = match kind { "create" => match toplevel { Some(toplevel) => { crate::priv_client::create_container_streaming( name, toplevel, - make_log_callback(logs.clone(), log_id, cmdline.clone()), + make_log_callback(logs.clone(), log_id, tag.clone()), ) .await } @@ -879,7 +968,7 @@ async fn priv_run_inner( crate::priv_client::update_container_streaming( name, toplevel, - make_log_callback(logs.clone(), log_id, cmdline.clone()), + make_log_callback(logs.clone(), log_id, tag.clone()), ) .await } @@ -903,6 +992,7 @@ async fn priv_run_inner( }; let succeeded = result.is_ok(); + tag.finished(succeeded, began.elapsed()); if let (Some(h), Some(id)) = (&logs, log_id) { h.finish( id, diff --git a/hive-c0re/src/lifecycle/tests.rs b/hive-c0re/src/lifecycle/tests.rs index 01954e3b..99582472 100644 --- a/hive-c0re/src/lifecycle/tests.rs +++ b/hive-c0re/src/lifecycle/tests.rs @@ -559,3 +559,93 @@ fn an_unknown_journal_op_keeps_the_start_error() { assert!(full.stderr.contains("Job failed"), "{}", full.stderr); assert!(!full.stderr.contains("unknown variant"), "{}", full.stderr); } + +/// One logged event: its level and each field as `name=value`. +type Event = (tracing::Level, Vec<(String, String)>); + +/// Every event a block logged. +#[derive(Clone, Default)] +struct Events(std::sync::Arc>>); + +impl tracing::Subscriber for Events { + fn enabled(&self, _: &tracing::Metadata<'_>) -> bool { + true + } + fn new_span(&self, _: &tracing::span::Attributes<'_>) -> tracing::span::Id { + tracing::span::Id::from_u64(1) + } + fn record(&self, _: &tracing::span::Id, _: &tracing::span::Record<'_>) {} + fn record_follows_from(&self, _: &tracing::span::Id, _: &tracing::span::Id) {} + fn event(&self, event: &tracing::Event<'_>) { + let mut fields = Vec::new(); + event.record( + &mut |field: &tracing::field::Field, value: &dyn std::fmt::Debug| { + fields.push((field.name().to_owned(), format!("{value:?}"))); + }, + ); + self.0 + .lock() + .unwrap() + .push((*event.metadata().level(), fields)); + } + fn enter(&self, _: &tracing::span::Id) {} + fn exit(&self, _: &tracing::span::Id) {} +} + +fn field<'a>(fields: &'a [(String, String)], name: &str) -> Option<&'a str> { + fields + .iter() + .find(|(n, _)| n == name) + .map(|(_, v)| v.as_str()) +} + +/// A build's log lines say which build they belong to, so the log store can +/// group them: a `start` line, the output lines, then a `finish` line with the +/// status and runtime. A nix error is a warning, chatter stays info, and a +/// failed finish is a warning. +#[test] +fn a_build_logs_its_start_its_lines_and_its_finish_under_one_build_id() { + use hive_priv_sock::PrivStream; + let events = Events::default(); + let _guard = tracing::subscriber::set_default(events.clone()); + let tag = BuildTag::new(Some(7), "alice", "update", "nixos-container update h-alice"); + tag.started(); + tag.line(PrivStream::Stdout, "copying 3 paths"); + tag.line(PrivStream::Stderr, "error: builder failed"); + tag.finished(false, std::time::Duration::from_secs(12)); + + let logged = events.0.lock().unwrap(); + assert_eq!(logged.len(), 4); + for (_, fields) in logged.iter() { + assert_eq!(field(fields, "build_id"), Some("7")); + assert_eq!(field(fields, "agent"), Some("alice")); + assert_eq!(field(fields, "kind"), Some("update")); + } + let levels: Vec<_> = logged.iter().map(|(l, _)| *l).collect(); + assert_eq!( + levels, + [ + tracing::Level::INFO, + tracing::Level::INFO, + tracing::Level::WARN, + tracing::Level::WARN + ] + ); + assert_eq!(field(&logged[0].1, "event"), Some("\"start\"")); + assert_eq!(field(&logged[1].1, "event"), None); + assert_eq!(field(&logged[3].1, "event"), Some("\"finish\"")); + assert_eq!(field(&logged[3].1, "status"), Some("\"fail\"")); + assert_eq!(field(&logged[3].1, "runtime_secs"), Some("12")); +} + +/// Without the build-log store there is no id; the lines still carry the +/// agent and kind, with an empty `build_id`. +#[test] +fn a_build_without_a_log_row_has_an_empty_build_id() { + let events = Events::default(); + let _guard = tracing::subscriber::set_default(events.clone()); + BuildTag::new(None, "alice", "create", "nixos-container create h-alice").started(); + let logged = events.0.lock().unwrap(); + assert_eq!(field(&logged[0].1, "build_id"), Some("")); + assert_eq!(field(&logged[0].1, "agent"), Some("alice")); +}