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

@@ -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

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<i64>, 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<std::sync::Arc<crate::build_logs::BuildLogs>>,
     log_id: Option<i64>,
-    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,

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<std::sync::Mutex<Vec<Event>>>);
+
+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"));
+}