feat(cli): debug command output in real time (#4318)

.changes/real-time-command-output.md

@@ -0,0 +1,7 @@
+---
+"cli.rs": patch
+"cli.js": patch
+"tauri-bundler": patch
+---
+
+Log command output in real time instead of waiting for it to finish.

tooling/bundler/src/bundle.rs

@@ -25,7 +25,7 @@ pub use self::{
 use log::{info, warn};
 pub use settings::{WindowsSettings, WixLanguage, WixLanguageConfig, WixSettings};
 
-use std::path::PathBuf;
+use std::{fmt::Write, path::PathBuf};
 
 /// Generated bundle metadata.
 #[derive(Debug)]
@@ -86,7 +86,7 @@ pub fn bundle_project(settings: Settings) -> crate::Result<Vec<Bundle>> {
       if bundle.package_type == crate::PackageType::Updater {
         note = " (updater)";
       }
-      printable_paths.push_str(&format!("        {}{}\n", path.display(), note));
+      writeln!(printable_paths, "        {}{}", path.display(), note).unwrap();
     }
   }
 

tooling/bundler/src/bundle/common.rs

@@ -7,9 +7,10 @@ use log::debug;
 use std::{
   ffi::OsStr,
   fs::{self, File},
-  io::{self, BufWriter},
+  io::{self, BufReader, BufWriter},
   path::Path,
-  process::{Command, Output},
+  process::{Command, Output, Stdio},
+  sync::{Arc, Mutex},
 };
 
 /// Returns true if the path has a filename indicating that it is a high-desity
@@ -139,25 +140,64 @@ pub trait CommandExt {
 
 impl CommandExt for Command {
   fn output_ok(&mut self) -> crate::Result<Output> {
-    debug!(action = "Running"; "Command `{} {}`", self.get_program().to_string_lossy(), self.get_args().map(|arg| arg.to_string_lossy()).fold(String::new(), |acc, arg| format!("{} {}", acc, arg)));
+    let program = self.get_program().to_string_lossy().into_owned();
+    debug!(action = "Running"; "Command `{} {}`", program, self.get_args().map(|arg| arg.to_string_lossy()).fold(String::new(), |acc, arg| format!("{} {}", acc, arg)));
 
-    let output = self.output()?;
+    self.stdout(Stdio::piped());
+    self.stderr(Stdio::piped());
 
-    let stdout = String::from_utf8_lossy(&output.stdout);
-    if !stdout.is_empty() {
-      debug!("Stdout: {}", stdout);
-    }
-    let stderr = String::from_utf8_lossy(&output.stderr);
-    if !stderr.is_empty() {
-      debug!("Stderr: {}", stderr);
-    }
+    let mut child = self.spawn()?;
+
+    let mut stdout = child.stdout.take().map(BufReader::new).unwrap();
+    let stdout_lines = Arc::new(Mutex::new(Vec::new()));
+    let stdout_lines_ = stdout_lines.clone();
+    std::thread::spawn(move || {
+      let mut buf = Vec::new();
+      let mut lines = stdout_lines_.lock().unwrap();
+      loop {
+        buf.clear();
+        match tauri_utils::io::read_line(&mut stdout, &mut buf) {
+          Ok(s) if s == 0 => break,
+          _ => (),
+        }
+        debug!(action = "stdout"; "{}", String::from_utf8_lossy(&buf));
+        lines.extend(buf.clone());
+        lines.push(b'\n');
+      }
+    });
+
+    let mut stderr = child.stderr.take().map(BufReader::new).unwrap();
+    let stderr_lines = Arc::new(Mutex::new(Vec::new()));
+    let stderr_lines_ = stderr_lines.clone();
+    std::thread::spawn(move || {
+      let mut buf = Vec::new();
+      let mut lines = stderr_lines_.lock().unwrap();
+      loop {
+        buf.clear();
+        match tauri_utils::io::read_line(&mut stderr, &mut buf) {
+          Ok(s) if s == 0 => break,
+          _ => (),
+        }
+        debug!(action = "stderr"; "{}", String::from_utf8_lossy(&buf));
+        lines.extend(buf.clone());
+        lines.push(b'\n');
+      }
+    });
+
+    let status = child.wait()?;
+    let output = Output {
+      status,
+      stdout: std::mem::take(&mut *stdout_lines.lock().unwrap()),
+      stderr: std::mem::take(&mut *stderr_lines.lock().unwrap()),
+    };
 
     if output.status.success() {
       Ok(output)
     } else {
-      Err(crate::Error::GenericError(
-        String::from_utf8_lossy(&output.stderr).to_string(),
-      ))
+      Err(crate::Error::GenericError(format!(
+        "failed to run {}",
+        program
+      )))
     }
   }
 }

tooling/bundler/src/bundle/platform.rs

@@ -41,7 +41,7 @@ pub fn target_triple() -> Result<String, crate::Error> {
   let arch_res = Command::new("rustc").args(&["--print", "cfg"]).output_ok();
 
   let arch = match arch_res {
-    Ok(output) => parse_rust_cfg(String::from_utf8_lossy(&output.stdout).into_owned())
+    Ok(output) => parse_rust_cfg(String::from_utf8_lossy(&output.stdout).into())
       .target_arch
       .expect("could not find `target_arch` when running `rustc --print cfg`."),
     Err(err) => {

tooling/cli/src/build.rs

@@ -81,8 +81,7 @@ pub fn command(options: Options) -> Result<()> {
         .arg(before_build)
         .current_dir(app_dir())
         .envs(command_env(options.debug))
-        .pipe()?
-        .status()
+        .piped()
         .with_context(|| format!("failed to run `{}` with `cmd /C`", before_build))?;
       #[cfg(not(target_os = "windows"))]
       let status = Command::new("sh")
@@ -90,8 +89,7 @@ pub fn command(options: Options) -> Result<()> {
         .arg(before_build)
         .current_dir(app_dir())
         .envs(command_env(options.debug))
-        .pipe()?
-        .status()
+        .piped()
         .with_context(|| format!("failed to run `{}` with `sh -c`", before_build))?;
 
       if !status.success() {

tooling/cli/src/dev.rs

@@ -9,7 +9,7 @@ use crate::{
     config::{get as get_config, reload as reload_config, AppUrl, ConfigHandle, WindowUrl},
     manifest::{rewrite_manifest, Manifest},
   },
-  CommandExt, Result,
+  Result,
 };
 use clap::Parser;
 
@@ -111,8 +111,7 @@ fn command_internal(options: Options) -> Result<()> {
           .arg("/C")
           .arg(before_dev)
           .current_dir(app_dir())
-          .envs(command_env(true))
-          .pipe()?; // development build always includes debug information
+          .envs(command_env(true));
         command
       };
       #[cfg(not(target_os = "windows"))]
@@ -122,11 +121,12 @@ fn command_internal(options: Options) -> Result<()> {
           .arg("-c")
           .arg(before_dev)
           .current_dir(app_dir())
-          .envs(command_env(true))
-          .pipe()?; // development build always includes debug information
+          .envs(command_env(true));
         command
       };
       command.stdin(Stdio::piped());
+      command.stdout(os_pipe::dup_stdout()?);
+      command.stderr(os_pipe::dup_stderr()?);
 
       let child = SharedChild::spawn(&mut command)
         .unwrap_or_else(|_| panic!("failed to run `{}`", before_dev));

tooling/cli/src/interface/rust.rs

@@ -101,15 +101,19 @@ struct CargoConfig {
 }
 
 pub fn build_project(runner: String, args: Vec<String>) -> crate::Result<()> {
-  Command::new(&runner)
+  let status = Command::new(&runner)
     .args(&["build", "--features=custom-protocol"])
     .args(args)
     .env("STATIC_VCRUNTIME", "true")
-    .pipe()?
-    .output_ok()
-    .with_context(|| format!("Result of `{} build` operation was unsuccessful", runner))?;
-
-  Ok(())
+    .piped()?;
+  if status.success() {
+    Ok(())
+  } else {
+    Err(anyhow::anyhow!(
+      "Result of `{} build` operation was unsuccessful",
+      runner
+    ))
+  }
 }
 
 pub struct AppSettings {

tooling/cli/src/lib.rs

@@ -19,8 +19,8 @@ use env_logger::Builder;
 use log::{debug, log_enabled, Level};
 use serde::Deserialize;
 use std::ffi::OsString;
-use std::io::Write;
-use std::process::{Command, Output};
+use std::io::{BufReader, Write};
+use std::process::{Command, ExitStatus, Stdio};
 
 #[derive(Deserialize)]
 pub struct VersionMetadata {
@@ -104,11 +104,16 @@ where
     .format_indent(Some(12))
     .filter(None, level_from_usize(cli.verbose).to_level_filter())
     .format(|f, record| {
+      let mut is_command_output = false;
       if let Some(action) = record.key_values().get("action".into()) {
-        let mut action_style = f.style();
-        action_style.set_color(Color::Green).set_bold(true);
+        let action = action.to_str().unwrap();
+        is_command_output = action == "stdout" || action == "stderr";
+        if !is_command_output {
+          let mut action_style = f.style();
+          action_style.set_color(Color::Green).set_bold(true);
 
-        write!(f, "{:>12} ", action_style.value(action.to_str().unwrap()))?;
+          write!(f, "{:>12} ", action_style.value(action))?;
+        }
       } else {
         let mut level_style = f.default_level_style(record.level());
         level_style.set_bold(true);
@@ -120,7 +125,7 @@ where
         )?;
       }
 
-      if log_enabled!(Level::Debug) {
+      if !is_command_output && log_enabled!(Level::Debug) {
         let mut target_style = f.style();
         target_style.set_color(Color::Black);
 
@@ -171,37 +176,61 @@ fn prettyprint_level(lvl: Level) -> &'static str {
 pub trait CommandExt {
   // The `pipe` function sets the stdout and stderr to properly
   // show the command output in the Node.js wrapper.
-  fn pipe(&mut self) -> Result<&mut Self>;
-  fn output_ok(&mut self) -> crate::Result<Output>;
+  fn piped(&mut self) -> Result<ExitStatus>;
+  fn output_ok(&mut self) -> crate::Result<()>;
 }
 
 impl CommandExt for Command {
-  fn pipe(&mut self) -> Result<&mut Self> {
+  fn piped(&mut self) -> crate::Result<ExitStatus> {
     self.stdout(os_pipe::dup_stdout()?);
     self.stderr(os_pipe::dup_stderr()?);
-    Ok(self)
+    let program = self.get_program().to_string_lossy().into_owned();
+    debug!(action = "Running"; "Command `{} {}`", program, self.get_args().map(|arg| arg.to_string_lossy()).fold(String::new(), |acc, arg| format!("{} {}", acc, arg)));
+
+    self.status().map_err(Into::into)
   }
 
-  fn output_ok(&mut self) -> crate::Result<Output> {
-    debug!(action = "Running"; "Command `{} {}`", self.get_program().to_string_lossy(), self.get_args().map(|arg| arg.to_string_lossy()).fold(String::new(), |acc, arg| format!("{} {}", acc, arg)));
+  fn output_ok(&mut self) -> crate::Result<()> {
+    let program = self.get_program().to_string_lossy().into_owned();
+    debug!(action = "Running"; "Command `{} {}`", program, self.get_args().map(|arg| arg.to_string_lossy()).fold(String::new(), |acc, arg| format!("{} {}", acc, arg)));
 
-    let output = self.output()?;
+    self.stdout(Stdio::piped());
+    self.stderr(Stdio::piped());
 
-    let stdout = String::from_utf8_lossy(&output.stdout);
-    if !stdout.is_empty() {
-      debug!("Stdout: {}", stdout);
-    }
-    let stderr = String::from_utf8_lossy(&output.stderr);
-    if !stderr.is_empty() {
-      debug!("Stderr: {}", stderr);
-    }
+    let mut child = self.spawn()?;
 
-    if output.status.success() {
-      Ok(output)
+    let mut stdout = child.stdout.take().map(BufReader::new).unwrap();
+    std::thread::spawn(move || {
+      let mut buf = Vec::new();
+      loop {
+        buf.clear();
+        match tauri_utils::io::read_line(&mut stdout, &mut buf) {
+          Ok(s) if s == 0 => break,
+          _ => (),
+        }
+        debug!(action = "stdout"; "{}", String::from_utf8_lossy(&buf));
+      }
+    });
+
+    let mut stderr = child.stderr.take().map(BufReader::new).unwrap();
+    std::thread::spawn(move || {
+      let mut buf = Vec::new();
+      loop {
+        buf.clear();
+        match tauri_utils::io::read_line(&mut stderr, &mut buf) {
+          Ok(s) if s == 0 => break,
+          _ => (),
+        }
+        debug!(action = "stderr"; "{}", String::from_utf8_lossy(&buf));
+      }
+    });
+
+    let status = child.wait()?;
+
+    if status.success() {
+      Ok(())
     } else {
-      Err(anyhow::anyhow!(
-        String::from_utf8_lossy(&output.stderr).to_string()
-      ))
+      Err(anyhow::anyhow!("failed to run {}", program))
     }
   }
 }