From 5dd831df405e2aff7501d22d1636b9e6a50ad470 Mon Sep 17 00:00:00 2001 From: Trevor Gross Date: Tue, 5 Aug 2025 22:23:44 -0500 Subject: [PATCH] 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" --- src/command_ext.rs | 18 +++++----- src/evaluator.rs | 2 +- src/justfile.rs | 2 +- src/platform/windows.rs | 4 +-- src/recipe.rs | 4 +-- src/signal_handler.rs | 20 +++++++++++ tests/fallback.rs | 1 + tests/misc.rs | 75 +++++++++++++++++++++++++++++++++++++++-- tests/test.rs | 47 ++++++++++++++++++++++++-- 9 files changed, 153 insertions(+), 20 deletions(-) diff --git a/src/command_ext.rs b/src/command_ext.rs index 1cd7ef0343..efb520ae76 100644 --- a/src/command_ext.rs +++ b/src/command_ext.rs @@ -11,11 +11,11 @@ pub(crate) trait CommandExt { fn export_scope(&mut self, settings: &Settings, scope: &Scope, unexports: &HashSet); - fn output_guard(self) -> (io::Result, Option); + fn output_guard(self, config: &Config) -> (io::Result, Option); - fn output_guard_stdout(self) -> Result; + fn output_guard_stdout(self, config: &Config) -> Result; - fn status_guard(self) -> (io::Result, Option); + fn status_guard(self, config: &Config) -> (io::Result, Option); } impl CommandExt for Command { @@ -53,12 +53,12 @@ impl CommandExt for Command { } } - fn output_guard(self) -> (io::Result, Option) { - SignalHandler::spawn(self, process::Child::wait_with_output) + fn output_guard(self, config: &Config) -> (io::Result, Option) { + SignalHandler::spawn(self, config, process::Child::wait_with_output) } - fn output_guard_stdout(self) -> Result { - let (result, caught) = self.output_guard(); + fn output_guard_stdout(self, config: &Config) -> Result { + 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, Option) { - SignalHandler::spawn(self, |mut child| child.wait()) + fn status_guard(self, config: &Config) -> (io::Result, Option) { + SignalHandler::spawn(self, config, |mut child| child.wait()) } } diff --git a/src/evaluator.rs b/src/evaluator.rs index e3a7166bab..2618058865 100644 --- a/src/evaluator.rs +++ b/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( diff --git a/src/justfile.rs b/src/justfile.rs index bf4623de84..8e3e8c8ad7 100644 --- a/src/justfile.rs +++ b/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(), diff --git a/src/platform/windows.rs b/src/platform/windows.rs index 13c5f32936..24e59ab540 100644 --- a/src/platform/windows.rs +++ b/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() diff --git a/src/recipe.rs b/src/recipe.rs index 11b8f2edac..86a7685cdf 100644 --- a/src/recipe.rs +++ b/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( diff --git a/src/signal_handler.rs b/src/signal_handler.rs index 0aee6e2695..3253a649ac 100644 --- a/src/signal_handler.rs +++ b/src/signal_handler.rs @@ -105,10 +105,30 @@ impl SignalHandler { pub(crate) fn spawn( mut command: Command, + config: &Config, f: impl Fn(process::Child) -> io::Result, ) -> (io::Result, Option) { 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, diff --git a/tests/fallback.rs b/tests/fallback.rs index 62e96b5966..765c78584b 100644 --- a/tests/fallback.rs +++ b/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") diff --git a/tests/misc.rs b/tests/misc.rs index 3c572bbe52..0d59314ff2 100644 --- a/tests/misc.rs +++ b/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(); } diff --git a/tests/test.rs b/tests/test.rs index a973212714..cfe76ef5d7 100644 --- a/tests/test.rs +++ b/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, pub(crate) expected_files: BTreeMap>, pub(crate) justfile: Option, + pub(crate) normalize_xtrace: bool, pub(crate) response: Option, pub(crate) shell: bool, pub(crate) status: i32, pub(crate) stderr: String, + pub(crate) stderr_fn: Option Result<(), String>>>, pub(crate) stderr_regex: Option, 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) -> 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, 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 = Lazy::new(|| { + Regex::new( + r#"(?mx)^ # multiline, verbose + (?P\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\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."); }