From ce6acf350e63c5c0d75a70fb763f072e3604d334 Mon Sep 17 00:00:00 2001 From: Alexander Grund Date: Mon, 15 Sep 2025 09:30:31 +0200 Subject: [PATCH 1/5] Make command environment of shell commands more discoverable in the log Put the command on an own, indented line so it is easier to find in the log. --- easybuild/tools/run.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index 87723e0e53..a28b077cfb 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -454,7 +454,7 @@ def to_cmd_str(cmd): cmd_name = fileprefix_from_cmd(os.path.basename(cmd_str.split(' ')[0])) tmpdir = tempfile.mkdtemp(dir=toptmpdir, prefix=f'{cmd_name}-') - _log.info(f'run_shell_cmd: command environment of "{cmd_str}" will be saved to {tmpdir}') + _log.info(f'run_shell_cmd: command environment of\n\t"{cmd_str}"\nwill be saved to {tmpdir}') cmd_out_fp = os.path.join(tmpdir, 'out.txt') _log.info(f'run_shell_cmd: Output of "{cmd_str}" will be logged to {cmd_out_fp}') From da8aa4e850d3256d46152db40d4aea49bee6a010 Mon Sep 17 00:00:00 2001 From: Alexander Grund Date: Mon, 15 Sep 2025 09:41:26 +0200 Subject: [PATCH 2/5] Combine log messages for run_shell_cmd into 1 --- easybuild/tools/run.py | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index a28b077cfb..ee4f3b909f 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -454,17 +454,20 @@ def to_cmd_str(cmd): cmd_name = fileprefix_from_cmd(os.path.basename(cmd_str.split(' ')[0])) tmpdir = tempfile.mkdtemp(dir=toptmpdir, prefix=f'{cmd_name}-') - _log.info(f'run_shell_cmd: command environment of\n\t"{cmd_str}"\nwill be saved to {tmpdir}') - cmd_out_fp = os.path.join(tmpdir, 'out.txt') - _log.info(f'run_shell_cmd: Output of "{cmd_str}" will be logged to {cmd_out_fp}') if split_stderr: cmd_err_fp = os.path.join(tmpdir, 'err.txt') - _log.info(f'run_shell_cmd: Errors and warnings of "{cmd_str}" will be logged to {cmd_err_fp}') else: cmd_err_fp = None cmd_sh = create_cmd_scripts(cmd_str, work_dir, env, tmpdir, cmd_out_fp, cmd_err_fp) + + log_str = f'Command environment of\n\t"{cmd_str}"\nwill be saved to {cmd_sh}\n' + log_str += f'Output will be logged to {cmd_out_fp}' + if cmd_err_fp: + log_str += f'\nErrors and warnings will be logged to {cmd_err_fp}' + _log.info(f'run_shell_cmd: {log_str}') + else: tmpdir, cmd_out_fp, cmd_err_fp, cmd_sh = None, None, None, None From 80c82eb8c20d6578b33a1a626e99fbbab6acad56 Mon Sep 17 00:00:00 2001 From: Alexander Grund Date: Wed, 24 Sep 2025 18:00:17 +0200 Subject: [PATCH 3/5] Don't show command string again when showing in which folder it runs. --- easybuild/tools/run.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index ee4f3b909f..ce7e37f840 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -471,13 +471,13 @@ def to_cmd_str(cmd): else: tmpdir, cmd_out_fp, cmd_err_fp, cmd_sh = None, None, None, None - interactive_msg = 'interactive ' if interactive else '' + cmd_type_msg = ('interactive ' if interactive else '') + ('shell command' if use_bash else 'command') # early exit in 'dry run' mode, after printing the command that would be run (unless 'hidden' is enabled) if not in_dry_run and build_option('extended_dry_run'): if not hidden or verbose_dry_run: silent = build_option('silent') - msg = f" running {interactive_msg}shell command \"{cmd_str}\"\n" + msg = f" running {cmd_type_msg} \"{cmd_str}\"\n" msg += f" (in {work_dir})" dry_run_msg(msg, silent=silent) @@ -505,7 +505,7 @@ def to_cmd_str(cmd): stderr_handle = subprocess.PIPE if split_stderr else subprocess.STDOUT stdin_handle = subprocess.PIPE if stdin or qa_patterns else subprocess.DEVNULL - log_msg = f"Running {interactive_msg}shell command '{cmd_str}' in {work_dir}" + log_msg = f"Running {cmd_type_msg} in {work_dir}" if thread_id: log_msg += f" (via thread with ID {thread_id})" _log.info(log_msg) From 67e19b1f96983d5902bf1bb79471078a17b8c1ee Mon Sep 17 00:00:00 2001 From: Alexander Grund Date: Fri, 26 Sep 2025 13:27:27 +0200 Subject: [PATCH 4/5] Fix test --- test/framework/run.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/framework/run.py b/test/framework/run.py index c7c4e0e66b..f294493679 100644 --- a/test/framework/run.py +++ b/test/framework/run.py @@ -447,7 +447,7 @@ def test_run_shell_cmd_log(self): fd, logfile = tempfile.mkstemp(suffix='.log', prefix='eb-test-') os.close(fd) - regex_start_cmd = re.compile("Running shell command 'echo hello' in /") + regex_start_cmd = re.compile("Running shell command in /") regex_cmd_exit = re.compile(r"Shell command completed successfully: echo hello") regex_cmd_output = re.compile(r"Output of 'echo \.\.\.' shell command \(stdout \+ stderr\):\nhello", re.M) From 0d8ce18a8363100d12428b5ca65f0d2f599c5456 Mon Sep 17 00:00:00 2001 From: Alexander Grund Date: Fri, 26 Sep 2025 13:42:37 +0200 Subject: [PATCH 5/5] Make logging of command consistent w.r.t. command type Use "shell command" or just "command" or "interactive [shell] command" in all places where it is logged. Additionally log the shortened command in more places like: "Running 'gcc ...' shell command in /tmp/fpp" "Output of 'gcc ...' shell command (stdout only):" --- easybuild/tools/run.py | 30 ++++++++++++++++-------------- test/framework/run.py | 2 +- 2 files changed, 17 insertions(+), 15 deletions(-) diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index ce7e37f840..f3c0bb040f 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -487,7 +487,7 @@ def to_cmd_str(cmd): start_time = datetime.now() if not hidden: - _cmd_trace_msg(cmd_str, start_time, work_dir, stdin, tmpdir, thread_id, interactive=interactive) + _cmd_trace_msg(cmd_type_msg, cmd_str, start_time, work_dir, stdin, tmpdir, thread_id) # use bash as shell instead of the default /bin/sh used by subprocess.run # (which could be dash instead of bash, like on Ubuntu, see https://wiki.ubuntu.com/DashAsBinSh) @@ -505,7 +505,10 @@ def to_cmd_str(cmd): stderr_handle = subprocess.PIPE if split_stderr else subprocess.STDOUT stdin_handle = subprocess.PIPE if stdin or qa_patterns else subprocess.DEVNULL - log_msg = f"Running {cmd_type_msg} in {work_dir}" + cmd_name = cmd_str.split(' ', 1)[0] + short_cmd_msg = f"'{cmd_name} ...' {cmd_type_msg}" # E.g. 'gcc ... shell command' + + log_msg = f"Running {short_cmd_msg} in {work_dir}" if thread_id: log_msg += f" (via thread with ID {thread_id})" _log.info(log_msg) @@ -614,19 +617,19 @@ def to_cmd_str(cmd): run_hook(RUN_SHELL_CMD, hooks, post_step_hook=True, args=[cmd], kwargs=run_hook_kwargs) # log command output (unless command was successful and log_output_on_success is disabled) - cmd_name = cmd_str.split(' ')[0] if split_stderr: - log_msg = f"Output of '{cmd_name} ...' shell command (stdout only):\n{res.output}\n\n" - log_msg += f"Warnings and errors of '{cmd_name} ...' shell command (stderr only):\n{res.stderr}" + log_msg = f"Output of {short_cmd_msg} (stdout only):\n{res.output}\n\n" + log_msg += f"Warnings and errors of {short_cmd_msg} (stderr only):\n{res.stderr}" else: - log_msg = f"Output of '{cmd_name} ...' shell command (stdout + stderr):\n{res.output}" + log_msg = f"Output of {short_cmd_msg} (stdout + stderr):\n{res.output}" + cmd_type_msg = cmd_type_msg[:1].upper() + cmd_type_msg[1:] # capitalize first letter if res.exit_code == EasyBuildExit.SUCCESS: - _log.info(f"Shell command completed successfully: {cmd_str}") + _log.info(f"{cmd_type_msg} completed successfully: {cmd_str}") if log_output_on_success: _log.info(log_msg) else: - _log.warning(f"Shell command FAILED (exit code {res.exit_code}): {cmd_str}") + _log.warning(f"{cmd_type_msg} FAILED (exit code {res.exit_code}): {cmd_str}") _log.info(log_msg) if fail_on_error: raise_run_shell_cmd_error(res) @@ -637,7 +640,7 @@ def to_cmd_str(cmd): os.getcwd() except FileNotFoundError: _log.warning( - f"Shell command `{cmd_str}` completed successfully but left the system in an unknown working directory. " + f"{short_cmd_msg} completed successfully but left the system in an unknown working directory. " f"Changing back to initial working directory: {initial_work_dir}" ) try: @@ -652,25 +655,24 @@ def to_cmd_str(cmd): return res -def _cmd_trace_msg(cmd, start_time, work_dir, stdin, tmpdir, thread_id, interactive=False): +def _cmd_trace_msg(cmd_type, cmd, start_time, work_dir, stdin, tmpdir, thread_id): """ Helper function to construct and print trace message for command being run + :param cmd_type: string describing the type of command being run (e.g., 'interactive shell command') :param cmd: command being run :param start_time: datetime object indicating when command was started :param work_dir: path of working directory in which command is run :param stdin: stdin input value for command :param tmpdir: path to temporary output directory for command :param thread_id: thread ID (None when not running shell command asynchronously) - :param interactive: boolean indicating whether it is an interactive command, or not """ start_time = start_time.strftime('%Y-%m-%d %H:%M:%S') - interactive = 'interactive ' if interactive else '' if thread_id: - run_cmd_msg = f"running {interactive}shell command (asynchronously, thread ID: {thread_id}):" + run_cmd_msg = f"running {cmd_type} (asynchronously, thread ID: {thread_id}):" else: - run_cmd_msg = f"running {interactive}shell command:" + run_cmd_msg = f"running {cmd_type}:" lines = [ run_cmd_msg, diff --git a/test/framework/run.py b/test/framework/run.py index f294493679..0f7b5a5d5c 100644 --- a/test/framework/run.py +++ b/test/framework/run.py @@ -447,7 +447,7 @@ def test_run_shell_cmd_log(self): fd, logfile = tempfile.mkstemp(suffix='.log', prefix='eb-test-') os.close(fd) - regex_start_cmd = re.compile("Running shell command in /") + regex_start_cmd = re.compile(r"Running 'echo \.\.\.' shell command in /") regex_cmd_exit = re.compile(r"Shell command completed successfully: echo hello") regex_cmd_output = re.compile(r"Output of 'echo \.\.\.' shell command \(stdout \+ stderr\):\nhello", re.M)