Print executed commands if run in verbose mode

It is currently difficult to debug what went wrong in cases such as OS
exec errors, because verbose output prints the file but does not say how
it is run. Update spawning to print executed commands with loquacious
and above verbosity. The result when run with `-v` is something like the
following:

    + cd "/home/user/workspace" && "/run/user/1000/just/just-kynaKD/configure"

The `+` syntax is meant to match shell scripts run with `-x`. This gets
coloring to differentiate it.

Environment variables are not printed unless `-vv` is set:

    + cd "/home/user/workspace" && RUST_BACKTRACE="1" CARGO_HOME="/cargo-home" "/run/user/1000/just/just-r2rLtg/configure"

Author: tgross35

src/command_ext.rs

@@ -11,11 +11,11 @@ pub(crate) trait CommandExt {
 
   fn export_scope(&mut self, settings: &Settings, scope: &Scope, unexports: &HashSet<String>);
 
-  fn output_guard(self) -> (io::Result<process::Output>, Option<Signal>);
+  fn output_guard(self, config: &Config) -> (io::Result<process::Output>, Option<Signal>);
 
-  fn output_guard_stdout(self) -> Result<String, OutputError>;
+  fn output_guard_stdout(self, config: &Config) -> Result<String, OutputError>;
 
-  fn status_guard(self) -> (io::Result<ExitStatus>, Option<Signal>);
+  fn status_guard(self, config: &Config) -> (io::Result<ExitStatus>, Option<Signal>);
 }
 
 impl CommandExt for Command {
@@ -53,12 +53,12 @@ impl CommandExt for Command {
     }
   }
 
-  fn output_guard(self) -> (io::Result<process::Output>, Option<Signal>) {
-    SignalHandler::spawn(self, process::Child::wait_with_output)
+  fn output_guard(self, config: &Config) -> (io::Result<process::Output>, Option<Signal>) {
+    SignalHandler::spawn(self, config, process::Child::wait_with_output)
   }
 
-  fn output_guard_stdout(self) -> Result<String, OutputError> {
-    let (result, caught) = self.output_guard();
+  fn output_guard_stdout(self, config: &Config) -> Result<String, OutputError> {
+    let (result, caught) = self.output_guard(config);
 
     let output = result.map_err(OutputError::Io)?;
 
@@ -79,7 +79,7 @@ impl CommandExt for Command {
     )
   }
 
-  fn status_guard(self) -> (io::Result<ExitStatus>, Option<Signal>) {
-    SignalHandler::spawn(self, |mut child| child.wait())
+  fn status_guard(self, config: &Config) -> (io::Result<ExitStatus>, Option<Signal>) {
+    SignalHandler::spawn(self, config, |mut child| child.wait())
   }
 }

src/evaluator.rs

@@ -291,7 +291,7 @@ impl<'src, 'run> Evaluator<'src, 'run> {
       })
       .stdout(Stdio::piped());
 
-    cmd.output_guard_stdout()
+    cmd.output_guard_stdout(self.context.config)
   }
 
   pub(crate) fn evaluate_line(

src/justfile.rs

@@ -158,7 +158,7 @@ impl<'src> Justfile<'src> {
 
         command.export(&self.settings, &dotenv, &scope, &self.unexports);
 
-        let (result, caught) = command.status_guard();
+        let (result, caught) = command.status_guard(config);
 
         let status = result.map_err(|io_error| Error::CommandInvoke {
           binary: binary.clone(),

src/platform/windows.rs

@@ -25,7 +25,7 @@ impl PlatformInterface for Platform {
         .stdout(Stdio::piped())
         .stderr(Stdio::piped());
 
-      Cow::Owned(cygpath.output_guard_stdout()?)
+      Cow::Owned(cygpath.output_guard_stdout(config)?)
     } else {
       // …otherwise use it as-is.
       Cow::Borrowed(shebang.interpreter)
@@ -69,7 +69,7 @@ impl PlatformInterface for Platform {
       .stdout(Stdio::piped())
       .stderr(Stdio::piped());
 
-    match cygpath.output_guard_stdout() {
+    match cygpath.output_guard_stdout(config) {
       Ok(shell_path) => Ok(shell_path),
       Err(_) => path
         .to_str()

src/recipe.rs

@@ -321,7 +321,7 @@ impl<'src, D> Recipe<'src, D> {
         &context.module.unexports,
       );
 
-      let (result, caught) = cmd.status_guard();
+      let (result, caught) = cmd.status_guard(context.config);
 
       match result {
         Ok(exit_status) => {
@@ -453,7 +453,7 @@ impl<'src, D> Recipe<'src, D> {
     );
 
     // run it!
-    let (result, caught) = command.status_guard();
+    let (result, caught) = command.status_guard(context.config);
 
     match result {
       Ok(exit_status) => exit_status.code().map_or_else(

src/signal_handler.rs

@@ -105,10 +105,30 @@ impl SignalHandler {
 
   pub(crate) fn spawn<T>(
     mut command: Command,
+    config: &Config,
     f: impl Fn(process::Child) -> io::Result<T>,
   ) -> (io::Result<T>, Option<Signal>) {
     let mut instance = Self::instance();
 
+    let color = config.color.context().stderr();
+    let pfx = color.prefix();
+    let sfx = color.suffix();
+
+    // Print an xtrace of run commands.
+    if config.verbosity.grandiloquent() {
+      // At the highest verbosity level, print the exact command as-is.
+      eprintln!("{pfx}+ {command:?}{sfx}");
+    } else if config.verbosity.loquacious() {
+      // For the second highest verbosity level, reconstruct the command but don't include
+      // environment (can be quite noisy with many `export`ed variables).
+      let mut dbg_cmd = Command::new(command.get_program());
+      dbg_cmd.args(command.get_args());
+      if let Some(cwd) = command.get_current_dir() {
+        dbg_cmd.current_dir(cwd);
+      }
+      eprintln!("{pfx}+ {dbg_cmd:?}{sfx}");
+    }
+
     let child = match command.spawn() {
       Err(err) => return (Err(err), None),
       Ok(child) => child,

tests/fallback.rs

@@ -61,6 +61,7 @@ fn fallback_from_subdir_verbose_message() {
       Trying ../justfile
       ===> Running recipe `bar`...
       echo bar
+      + COMMAND_XTRACE
       ",
     ))
     .stdout("bar\n")

tests/misc.rs

@@ -232,7 +232,55 @@ fn verbose() {
     .arg("--verbose")
     .justfile("default:\n @echo hello")
     .stdout("hello\n")
-    .stderr("===> Running recipe `default`...\necho hello\n")
+    .stderr(
+      "\
+      ===> Running recipe `default`...\n\
+      echo hello\n\
+      + COMMAND_XTRACE\n\
+      ",
+    )
+    .run();
+}
+
+#[test]
+fn xtrace() {
+  Test::new()
+    .arg("--verbose")
+    .justfile(
+      r#"
+export ENV := "hi"
+a:
+  echo $ENV
+"#,
+    )
+    .normalize_xtrace(false)
+    .stdout("hi\n")
+    .stderr_fn(|s| {
+      // The lowest verbosity mode shouldn't print ENV. Easier to check with a function
+      // than with regex.
+      if s.contains("ENV=") {
+        return Err("shouldn't print env".into());
+      }
+      Ok(())
+    })
+    .stderr_regex(r".*\+ cd.*&&.*echo \$ENV.*")
+    .run();
+}
+
+#[test]
+fn xtrace_very_verbose() {
+  Test::new()
+    .arg("-vv")
+    .justfile(
+      r#"
+export ENV := "hi"
+a:
+  echo $ENV
+"#,
+    )
+    .normalize_xtrace(false)
+    .stdout("hi\n")
+    .stderr_regex(r".*\+ cd.*&&.*ENV=.*echo \$ENV.*")
     .run();
 }
 
@@ -2037,7 +2085,13 @@ a:
 ",
     )
     .stdout("hi\n")
-    .stderr("\u{1b}[1;36m===> Running recipe `a`...\u{1b}[0m\n\u{1b}[1mecho hi\u{1b}[0m\n")
+    .stderr(
+      "\
+      \u{1b}[1;36m===> Running recipe `a`...\u{1b}[0m\n\
+      \u{1b}[1mecho hi\u{1b}[0m\n\
+      \u{1b}[1;34m+ COMMAND_XTRACE\u{1b}[0m\n\
+      ",
+    )
     .run();
 }
 
@@ -2057,7 +2111,13 @@ a:
 ",
     )
     .stdout("hi\n")
-    .stderr("\u{1b}[1;36m===> Running recipe `a`...\u{1b}[0m\necho hi\n")
+    .stderr(
+      "\
+      \u{1b}[1;36m===> Running recipe `a`...\u{1b}[0m\n\
+      echo hi\n\
+      \u{1b}[1;34m+ COMMAND_XTRACE\u{1b}[0m\n\
+      ",
+    )
     .run();
 }
 

tests/test.rs

@@ -1,5 +1,6 @@
 use {
   super::*,
+  once_cell::sync::Lazy,
   pretty_assertions::{assert_eq, StrComparison},
 };
 
@@ -16,10 +17,12 @@ pub(crate) struct Test {
   pub(crate) env: BTreeMap<String, String>,
   pub(crate) expected_files: BTreeMap<PathBuf, Vec<u8>>,
   pub(crate) justfile: Option<String>,
+  pub(crate) normalize_xtrace: bool,
   pub(crate) response: Option<Response>,
   pub(crate) shell: bool,
   pub(crate) status: i32,
   pub(crate) stderr: String,
+  pub(crate) stderr_fn: Option<Box<dyn Fn(&str) -> Result<(), String>>>,
   pub(crate) stderr_regex: Option<Regex>,
   pub(crate) stdin: String,
   pub(crate) stdout: String,
@@ -46,12 +49,14 @@ impl Test {
       status: EXIT_SUCCESS,
       stderr: String::new(),
       stderr_regex: None,
+      stderr_fn: None,
       stdin: String::new(),
       stdout: String::new(),
       stdout_regex: None,
       tempdir,
       test_round_trip: true,
       unindent_stdout: true,
+      normalize_xtrace: true,
     }
   }
 
@@ -132,6 +137,11 @@ impl Test {
     self
   }
 
+  pub(crate) fn stderr_fn(mut self, f: impl Fn(&str) -> Result<(), String> + 'static) -> Self {
+    self.stderr_fn = Some(Box::from(f));
+    self
+  }
+
   pub(crate) fn stdin(mut self, stdin: impl Into<String>) -> Self {
     self.stdin = stdin.into();
     self
@@ -164,6 +174,11 @@ impl Test {
     self
   }
 
+  pub(crate) fn normalize_xtrace(mut self, normalize_xtrace: bool) -> Self {
+    self.normalize_xtrace = normalize_xtrace;
+    self
+  }
+
   pub(crate) fn write(self, path: impl AsRef<Path>, content: impl AsRef<[u8]>) -> Self {
     let path = self.tempdir.path().join(path);
     fs::create_dir_all(path.parent().unwrap()).unwrap();
@@ -204,6 +219,18 @@ impl Test {
   }
 }
 
+static XTRACE_RE: Lazy<Regex> = Lazy::new(|| {
+  Regex::new(
+    r#"(?mx)^                  # multiline, verbose
+    (?P<pfx>\u{1b}\[[\d;]+m)?  # match the color prefix, if available
+    \+.*bash.*?                # match the command. Currently all tests that pass `--verbose` are
+                               # run on bash, so this matcher is "good enough" for now.
+    (?P<sfx>\u{1b}\[[\d;]+m)?  # match the color suffix, if available
+    $"#,
+  )
+  .unwrap()
+});
+
 impl Test {
   #[track_caller]
   pub(crate) fn run(self) -> Output {
@@ -267,7 +294,14 @@ impl Test {
       .expect("failed to wait for just process");
 
     let output_stdout = str::from_utf8(&output.stdout).unwrap();
-    let output_stderr = str::from_utf8(&output.stderr).unwrap();
+    let mut output_stderr = str::from_utf8(&output.stderr).unwrap();
+
+    // The xtrace output can differ by working directory, shell, and flags. Normalize it.
+    let tmp;
+    if self.normalize_xtrace {
+      tmp = XTRACE_RE.replace_all(output_stderr, "${pfx}+ COMMAND_XTRACE${sfx}");
+      output_stderr = tmp.as_ref();
+    }
 
     if let Some(ref stdout_regex) = self.stdout_regex {
       assert!(
@@ -283,9 +317,18 @@ impl Test {
       );
     }
 
+    if let Some(ref stderr_fn) = self.stderr_fn {
+      match stderr_fn(output_stderr) {
+        Ok(()) => (),
+        Err(e) => panic!("Stderr function mismatch: {e}\n{output_stderr:?}\n",),
+      }
+    }
+
     if !compare("status", output.status.code(), Some(self.status))
       | (self.stdout_regex.is_none() && !compare_string("stdout", output_stdout, &stdout))
-      | (self.stderr_regex.is_none() && !compare_string("stderr", output_stderr, &stderr))
+      | (self.stderr_regex.is_none()
+        && self.stderr_fn.is_none()
+        && !compare_string("stderr", output_stderr, &stderr))
     {
       panic!("Output mismatch.");
     }