improve logging of recipe steps

crates/rugpi-bakery/src/cli/mod.rs

@@ -11,6 +11,8 @@ mod cmds;
 
 pub mod args;
 
+pub(crate) mod status;
+
 /// Run Rugix Bakery with the provided command line arguments.
 pub async fn run(args: args::Args) -> BakeryResult<()> {
     match &args.cmd {

crates/rugpi-bakery/src/cli/status.rs

@@ -0,0 +1,51 @@
+use std::collections::VecDeque;
+
+use rugpi_cli::style::Stylize;
+use rugpi_cli::widgets::{Heading, Text, Widget};
+use rugpi_cli::{StatusSegment, VisualHeight};
+
+#[derive(Debug, Default)]
+pub struct CliLog {
+    state: std::sync::Mutex<CliLogState>,
+    title: String,
+    line_limit: usize,
+}
+
+impl CliLog {
+    pub fn new(title: String) -> Self {
+        Self {
+            state: std::sync::Mutex::default(),
+            title,
+            line_limit: 15,
+        }
+    }
+
+    pub fn push_line(&self, line: String) {
+        let mut state = self.state.lock().unwrap();
+        state.lines.push_back(line);
+        while state.lines.len() > self.line_limit {
+            state.lines.pop_front();
+        }
+    }
+}
+
+#[derive(Debug, Default)]
+struct CliLogState {
+    lines: VecDeque<String>,
+}
+
+impl StatusSegment for CliLog {
+    fn draw(&self, ctx: &mut rugpi_cli::DrawCtx) {
+        Heading::new(&self.title).draw(ctx);
+        let state = self.state.lock().unwrap();
+        let show_lines = VisualHeight::from_usize(state.lines.len())
+            .min(ctx.measure_remaining_height())
+            .into_u64() as usize;
+        let skip_lines = state.lines.len() - show_lines;
+        Text::new(state.lines.iter().skip(skip_lines))
+            .prefix("> ")
+            .styled()
+            .dark_gray()
+            .draw(ctx);
+    }
+}

crates/rugpi-bakery/src/oven/customize.rs

@@ -1,17 +1,22 @@
 //! Applies a set of recipes to a system.
 
 use std::collections::{HashMap, HashSet};
+use std::ffi::OsString;
 use std::fs;
 use std::ops::Deref;
 use std::path::Path;
+use std::process::Stdio;
 use std::sync::Arc;
 
 use reportify::{bail, ResultExt};
+use rugpi_cli::StatusSegmentRef;
 use rugpi_common::mount::{MountStack, Mounted};
 use tempfile::tempdir;
+use tokio::io::{AsyncRead, AsyncReadExt, AsyncWriteExt};
 use tracing::{error, info};
-use xscript::{cmd, run, vars, ParentEnv, Run};
+use xscript::{cmd, run, vars, Cmd, ParentEnv, Run};
 
+use crate::cli::status::CliLog;
 use crate::config::layers::LayerConfig;
 use crate::config::projects::Architecture;
 use crate::project::layers::Layer;
@@ -22,6 +27,45 @@ use crate::project::ProjectRef;
 use crate::utils::caching::{mtime, mtime_recursive};
 use crate::BakeryResult;
 
+struct Logger {
+    cli_log: StatusSegmentRef<CliLog>,
+    state: tokio::sync::Mutex<LoggerState>,
+}
+
+struct LoggerState {
+    log_file: tokio::fs::File,
+    line_buffer: Vec<u8>,
+}
+
+impl Logger {
+    pub async fn new(layer_name: &str, layer_path: &Path) -> BakeryResult<Self> {
+        let log_file = tokio::fs::File::create(layer_path.join("build.log"))
+            .await
+            .whatever("error creating layer log file")?;
+        Ok(Self {
+            cli_log: rugpi_cli::add_status(CliLog::new(format!("Layer: {layer_name}"))),
+            state: tokio::sync::Mutex::new(LoggerState {
+                log_file,
+                line_buffer: Vec::new(),
+            }),
+        })
+    }
+
+    pub async fn write(&self, bytes: &[u8]) {
+        let mut state = self.state.lock().await;
+        let _ = state.log_file.write_all(&bytes).await;
+        for b in bytes {
+            if *b == b'\n' {
+                self.cli_log
+                    .push_line(String::from_utf8_lossy(&state.line_buffer).into_owned());
+                state.line_buffer.clear();
+            } else {
+                state.line_buffer.push(*b);
+            }
+        }
+    }
+}
+
 pub async fn customize(
     project: &ProjectRef,
     arch: Architecture,
@@ -80,7 +124,11 @@ pub async fn customize(
     }
     let root_dir = bundle_dir.join("roots/system");
     std::fs::create_dir_all(&root_dir).ok();
-    apply_recipes(project, arch, &jobs, bundle_dir, &root_dir, layer_path)?;
+    let logger = Logger::new(&layer.name, layer_path).await?;
+    apply_recipes(
+        &logger, project, arch, &jobs, bundle_dir, &root_dir, layer_path,
+    )
+    .await?;
     info!("packing system files");
     run!(["tar", "-c", "-f", &target, "-C", bundle_dir, "."])
         .whatever("unable to package system files")?;
@@ -179,7 +227,58 @@ fn recipe_schedule(
     Ok(recipes)
 }
 
-fn apply_recipes(
+async fn run_cmd(logger: &Logger, cmd: Cmd<OsString>) -> BakeryResult<()> {
+    let mut command = tokio::process::Command::new(cmd.prog());
+    command.args(cmd.args());
+    if let Some(vars) = cmd.vars() {
+        if vars.is_clean() {
+            command.env_clear();
+        }
+        for (name, value) in vars.values() {
+            if let Some(value) = value {
+                command.env(name, value);
+            } else {
+                command.env_remove(name);
+            }
+        }
+    }
+    command
+        .stdin(Stdio::null())
+        .stdout(Stdio::piped())
+        .stderr(Stdio::piped())
+        .kill_on_drop(true);
+    let mut child = command
+        .spawn()
+        .whatever_with(|_| format!("unable to spawn command {cmd}"))?;
+    let stdout = child.stdout.take().unwrap();
+    let stderr = child.stderr.take().unwrap();
+
+    async fn copy_log<R: Unpin + AsyncRead>(logger: &Logger, mut reader: R) {
+        let mut buffer = Vec::with_capacity(8192);
+        while let Ok(read) = reader.read_buf(&mut buffer).await {
+            if read == 0 {
+                break;
+            }
+            logger.write(&buffer[..read]).await;
+            buffer.clear();
+        }
+    }
+
+    let (_, _, status) = tokio::join!(
+        copy_log(logger, stdout),
+        copy_log(logger, stderr),
+        child.wait()
+    );
+
+    let status = status.whatever_with(|_| format!("unable to spawn command {cmd}"))?;
+    if !status.success() {
+        bail!("failed with exit code {}", status.code().unwrap_or(1));
+    }
+    Ok(())
+}
+
+async fn apply_recipes(
+    logger: &Logger,
     project: &ProjectRef,
     arch: Architecture,
     jobs: &[RecipeJob],
@@ -304,11 +403,15 @@ fn apply_recipes(
                     for (name, value) in &job.parameters {
                         vars.set(format!("RECIPE_PARAM_{}", name.to_uppercase()), value);
                     }
-                    run!(["chroot", root_dir_path, &script]
-                        .with_stdout(xscript::Out::Inherit)
-                        .with_stderr(xscript::Out::Inherit)
-                        .with_vars(vars))
-                    .whatever("unable to run `chroot`")?;
+                    run_cmd(
+                        logger,
+                        Cmd::new("chroot")
+                            .add_arg(root_dir_path)
+                            .add_arg(&script)
+                            .clone()
+                            .with_vars(vars),
+                    )
+                    .await?;
                 }
                 StepKind::Run => {
                     let script = recipe.path.join("steps").join(&step.filename);
@@ -325,11 +428,7 @@ fn apply_recipes(
                     for (name, value) in &job.parameters {
                         vars.set(format!("RECIPE_PARAM_{}", name.to_uppercase()), value);
                     }
-                    run!([&script]
-                        .with_stdout(xscript::Out::Inherit)
-                        .with_stderr(xscript::Out::Inherit)
-                        .with_vars(vars))
-                    .whatever("unable to run script")?;
+                    run_cmd(logger, Cmd::new(&script).with_vars(vars)).await?;
                 }
             }
         }

crates/rugpi-bakery/src/tester/qemu.rs

@@ -1,4 +1,3 @@
-use std::collections::VecDeque;
 use std::os::unix::fs::MetadataExt;
 use std::path::Path;
 use std::process::Stdio;
@@ -10,9 +9,6 @@ use xscript::{run, RunAsync};
 use async_trait::async_trait;
 use byte_calc::NumBytes;
 use reportify::{bail, whatever, ErrorExt, Report, ResultExt, Whatever};
-use rugpi_cli::style::Stylize;
-use rugpi_cli::widgets::{Heading, Text, Widget};
-use rugpi_cli::{StatusSegment, VisualHeight};
 
 use russh::client::Handle;
 use russh::keys::key::PrivateKeyWithHashAlg;
@@ -26,6 +22,7 @@ use tokio::sync::{oneshot, Mutex};
 use tokio::{fs, time};
 use tracing::{error, info};
 
+use crate::cli::status::CliLog;
 use crate::config::projects::Architecture;
 use crate::config::tests::SystemConfig;
 use crate::BakeryResult;
@@ -340,7 +337,7 @@ pub async fn start(
             .whatever("unable to create stdout log file")?;
         let mut stdout = child.stdout.take().expect("we used Stdio::piped");
         tokio::spawn(async move {
-            let log = rugpi_cli::add_status(VmLog::default());
+            let log = rugpi_cli::add_status(CliLog::default());
             let mut line_buffer = Vec::new();
             let mut buffer = Vec::with_capacity(8096);
             while let Ok(read) = stdout.read_buf(&mut buffer).await {
@@ -429,39 +426,3 @@ impl russh::client::Handler for SshHandler {
         Ok(true)
     }
 }
-
-#[derive(Debug, Default)]
-struct VmLog {
-    state: std::sync::Mutex<VmLogState>,
-}
-
-impl VmLog {
-    fn push_line(&self, line: String) {
-        let mut state = self.state.lock().unwrap();
-        state.lines.push_back(line);
-        while state.lines.len() > 15 {
-            state.lines.pop_front();
-        }
-    }
-}
-
-#[derive(Debug, Default)]
-struct VmLogState {
-    lines: VecDeque<String>,
-}
-
-impl StatusSegment for VmLog {
-    fn draw(&self, ctx: &mut rugpi_cli::DrawCtx) {
-        Heading::new("VM Output").draw(ctx);
-        let state = self.state.lock().unwrap();
-        let show_lines = VisualHeight::from_usize(state.lines.len())
-            .min(ctx.measure_remaining_height())
-            .into_u64() as usize;
-        let skip_lines = state.lines.len() - show_lines;
-        Text::new(state.lines.iter().skip(skip_lines))
-            .prefix("> ")
-            .styled()
-            .dark_gray()
-            .draw(ctx);
-    }
-}