Print executed commands if run in verbose mode

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,64 @@ 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 MESSAGE := "hi"
+a:
+  echo $MESSAGE
+"#,
+    )
+    .normalize_xtrace(false)
+    .stdout("hi\n")
+    .stderr_fn(|s| {
+      // The lowest verbosity mode shouldn't print MESSAGE. Easier to check with a function
+      // than with regex.
+      if s.contains("MESSAGE=") {
+        return Err("shouldn't print env".into());
+      }
+      Ok(())
+    })
+    .stderr_regex(if cfg!(windows) {
+      r".*\+ .*echo \$MESSAGE.*"
+    } else {
+      r".*\+ cd.*&&.*echo \$MESSAGE.*"
+    })
+    .run();
+}
+
+#[test]
+fn xtrace_very_verbose() {
+  Test::new()
+    .arg("-vv")
+    .justfile(
+      r#"
+export MESSAGE := "hi"
+a:
+  echo $MESSAGE
+"#,
+    )
+    .normalize_xtrace(false)
+    .stdout("hi\n")
+    .stderr_regex(if cfg!(windows) {
+      // `Debug for Command` doesn't print env on windows
+      r".*\+ .*echo \$MESSAGE.*"
+    } else {
+      r".*\+ cd.*&&.*MESSAGE=.*echo \$MESSAGE.*"
+    })
     .run();
 }
 
@@ -2037,7 +2094,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 +2120,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.");
     }