a failed container start shows the unit's own journal lines in the op output

hive-priv/src/container.rs

@@ -49,6 +49,80 @@ pub(crate) async fn start_container(name: &str) -> Result<(String, String)> {
     container_run(&["start", &machine]).await
 }
 
+/// Most bytes of journal text `StartFailureLog` returns.
+const START_LOG_CAP: usize = 8 * 1024;
+/// Longest `journalctl` run.
+const START_LOG_TIMEOUT: std::time::Duration = std::time::Duration::from_secs(5);
+/// How far back `StartFailureLog` may look.
+const START_LOG_MAX_LOOKBACK_SECS: u64 = 3600;
+
+/// The fixed `journalctl` argv for `machine`'s start log. The match is
+/// `_SYSTEMD_UNIT`, so only lines written by the container unit's own
+/// processes come back, not systemd's job messages about it.
+fn start_log_argv(machine: &str, since: u64) -> Vec<String> {
+    [
+        &format!("_SYSTEMD_UNIT=container@{machine}.service"),
+        "--since",
+        &format!("@{since}"),
+        "-n",
+        "30",
+        "-o",
+        "cat",
+        "--no-pager",
+    ]
+    .map(str::to_owned)
+    .to_vec()
+}
+
+/// The last `cap` bytes of `text`, cut at a char boundary.
+fn tail_bytes(text: &str, cap: usize) -> &str {
+    let mut start = text.len().saturating_sub(cap);
+    while !text.is_char_boundary(start) {
+        start += 1;
+    }
+    &text[start..]
+}
+
+/// `StartFailureLog`: the container unit's recent journal lines, capped.
+/// `run` executes `journalctl` with the argv it is given.
+async fn start_failure_log_with<F, Fut>(
+    name: &str,
+    since_unix: u64,
+    now: u64,
+    run: F,
+) -> Result<(String, String)>
+where
+    F: FnOnce(Vec<String>) -> Fut,
+    Fut: std::future::Future<Output = Result<String>>,
+{
+    validate_agent_name(name)?;
+    let since = since_unix.clamp(now.saturating_sub(START_LOG_MAX_LOOKBACK_SECS), now);
+    let out = run(start_log_argv(&container_system_name(name), since)).await?;
+    Ok((tail_bytes(&out, START_LOG_CAP).to_owned(), String::new()))
+}
+
+/// `StartFailureLog` against the real `journalctl`.
+pub(crate) async fn start_failure_log(name: &str, since_unix: u64) -> Result<(String, String)> {
+    let now = std::time::SystemTime::now()
+        .duration_since(std::time::UNIX_EPOCH)
+        .map_or(0, |d| d.as_secs());
+    start_failure_log_with(name, since_unix, now, |argv| async move {
+        let child = Command::new("journalctl")
+            .args(&argv)
+            .kill_on_drop(true)
+            .output();
+        let out = tokio::time::timeout(START_LOG_TIMEOUT, child)
+            .await
+            .context("journalctl timed out")?
+            .context("invoke journalctl")?;
+        if !out.status.success() {
+            bail!("journalctl failed ({})", out.status);
+        }
+        Ok(String::from_utf8_lossy(&out.stdout).into_owned())
+    })
+    .await
+}
+
 /// `StopContainer`.
 pub(crate) async fn stop_container(name: &str) -> Result<(String, String)> {
     validate_agent_name(name)?;
@@ -635,3 +709,68 @@ mod tests {
         }
     }
 }
+
+#[cfg(test)]
+mod start_log_tests {
+    use super::*;
+
+    const NOW: u64 = 1_000_000;
+
+    async fn argv_for(name: &str, since: u64) -> Vec<String> {
+        let seen = std::sync::Mutex::new(Vec::new());
+        start_failure_log_with(name, since, NOW, |argv| {
+            *seen.lock().unwrap() = argv;
+            async { Ok(String::new()) }
+        })
+        .await
+        .unwrap();
+        seen.into_inner().unwrap()
+    }
+
+    #[tokio::test]
+    async fn odd_names_are_refused_before_journalctl_runs() {
+        for bad in ["", "../x", "a b", "A", "x.service", "x\n--vacuum-size=1"] {
+            let r =
+                start_failure_log_with(bad, NOW, NOW, |_| async { panic!("runner must not run") })
+                    .await;
+            assert!(r.is_err(), "{bad:?} accepted");
+        }
+    }
+
+    #[tokio::test]
+    async fn the_argv_is_fixed_and_the_unit_is_built_here() {
+        assert_eq!(
+            argv_for("bob", NOW - 5).await,
+            [
+                "_SYSTEMD_UNIT=container@h-bob.service",
+                "--since",
+                "@999995",
+                "-n",
+                "30",
+                "-o",
+                "cat",
+                "--no-pager"
+            ]
+        );
+    }
+
+    #[tokio::test]
+    async fn since_is_clamped_to_the_last_hour_and_not_the_future() {
+        assert_eq!(argv_for("bob", 0).await[2], format!("@{}", NOW - 3600));
+        assert_eq!(argv_for("bob", NOW + 99).await[2], format!("@{NOW}"));
+    }
+
+    #[tokio::test]
+    async fn the_output_is_capped_keeping_the_newest_bytes() {
+        let big = format!("{}end\n", "é".repeat(START_LOG_CAP));
+        let (out, _) = start_failure_log_with("bob", NOW, NOW, |_| async { Ok(big) })
+            .await
+            .unwrap();
+        assert!(out.len() <= START_LOG_CAP, "{}", out.len());
+        assert!(out.ends_with("end\n"));
+        let (small, _) = start_failure_log_with("bob", NOW, NOW, |_| async { Ok("a\n".into()) })
+            .await
+            .unwrap();
+        assert_eq!(small, "a\n");
+    }
+}

hive-priv/src/main.rs

@@ -360,6 +360,11 @@ async fn exec(
     match req {
         PrivRequest::StartContainer { ref name } => container::start_container(name).await,
 
+        PrivRequest::StartFailureLog {
+            ref name,
+            since_unix,
+        } => container::start_failure_log(name, since_unix).await,
+
         PrivRequest::StopContainer { ref name } => container::stop_container(name).await,
 
         PrivRequest::KillContainer { ref name } => container::kill_container(name).await,