diff --git a/easybuild/framework/easyblock.py b/easybuild/framework/easyblock.py index ce5a9663f5..86d0cd340f 100644 --- a/easybuild/framework/easyblock.py +++ b/easybuild/framework/easyblock.py @@ -1875,7 +1875,7 @@ def clean_up_fake_module(self, fake_mod_data): # self.short_mod_name might not be set (e.g. during unit tests) if fake_mod_path and self.short_mod_name is not None: try: - self.modules_tool.unload([self.short_mod_name]) + self.modules_tool.unload([self.short_mod_name], log_changes=False) self.modules_tool.remove_module_path(os.path.join(fake_mod_path, self.mod_subdir)) remove_dir(os.path.dirname(fake_mod_path)) except OSError as err: @@ -1884,7 +1884,8 @@ def clean_up_fake_module(self, fake_mod_data): self.log.warning("Not unloading module, since self.short_mod_name is not set.") # restore original environment - restore_env(env) + self.log.info("Restoring environment after unloading fake module") + restore_env(env, log_changes=False) def load_dependency_modules(self): """Load dependency modules.""" diff --git a/easybuild/tools/environment.py b/easybuild/tools/environment.py index cf6bb2e09c..f8aea7942a 100644 --- a/easybuild/tools/environment.py +++ b/easybuild/tools/environment.py @@ -76,12 +76,13 @@ def get_changes(): return _changes -def setvar(key, value, verbose=True): +def setvar(key, value, verbose=True, log_changes=True): """ put key in the environment with value tracks added keys until write_changes has been called :param verbose: include message in dry run output for defining this environment variable + :param log_changes: show the change in the log """ try: oldval_info = "previous value: '%s'" % os.environ[key] @@ -90,7 +91,8 @@ def setvar(key, value, verbose=True): # os.putenv() is not necessary. os.environ will call this. os.environ[key] = value _changes[key] = value - _log.info("Environment variable %s set to %s (%s)", key, value, oldval_info) + if log_changes: + _log.info("Environment variable %s set to %s (%s)", key, value, oldval_info) if verbose and build_option('extended_dry_run'): quoted_value = shell_quote(value) @@ -149,23 +151,22 @@ def read_environment(env_vars, strict=False): return result -def modify_env(old, new, verbose=True): +def modify_env(old, new, verbose=True, log_changes=True): """ Compares two os.environ dumps. Adapts final environment. + :param log_changes: show the change in the log """ old_keys = list(old.keys()) new_keys = list(new.keys()) for key in new_keys: - # set them all. no smart checking for changed/identical values if key in old_keys: - # hmm, smart checking with debug logging - if not new[key] == old[key]: + if new[key] != old[key]: _log.debug("Key in new environment found that is different from old one: %s (%s)", key, new[key]) - setvar(key, new[key], verbose=verbose) + setvar(key, new[key], verbose=verbose, log_changes=log_changes) else: _log.debug("Key in new environment found that is not in old one: %s (%s)", key, new[key]) - setvar(key, new[key], verbose=verbose) + setvar(key, new[key], verbose=verbose, log_changes=log_changes) for key in old_keys: if key not in new_keys: @@ -174,11 +175,12 @@ def modify_env(old, new, verbose=True): del os.environ[key] -def restore_env(env): +def restore_env(env, log_changes=True): """ Restore active environment based on specified dictionary. + :param log_changes: show the change in the log """ - modify_env(os.environ, env, verbose=False) + modify_env(os.environ, env, verbose=False, log_changes=log_changes) def sanitize_env(): diff --git a/easybuild/tools/modules.py b/easybuild/tools/modules.py index 6a78d9ca6d..b64f769275 100644 --- a/easybuild/tools/modules.py +++ b/easybuild/tools/modules.py @@ -1121,12 +1121,12 @@ def load(self, modules, mod_paths=None, purge=False, init_env=None, allow_reload if allow_reload or mod not in loaded_modules: self.run_module('load', mod) - def unload(self, modules=None): + def unload(self, modules, log_changes=True): """ Unload all requested modules. """ for mod in modules: - self.run_module('unload', mod) + self.run_module('unload', mod, log_changes=log_changes) def purge(self): """ @@ -1189,9 +1189,9 @@ def modulefile_path(self, mod_name, strip_ext=False): return modpath - def set_path_env_var(self, key, paths): + def set_path_env_var(self, key, paths, log_changes=True): """Set path environment variable to the given list of paths.""" - setvar(key, os.pathsep.join(paths), verbose=False) + setvar(key, os.pathsep.join(paths), verbose=False, log_changes=log_changes) def check_module_output(self, cmd, stdout, stderr): """Check output of 'module' command, see if if is potentially invalid.""" @@ -1250,11 +1250,13 @@ def run_module(self, *args, **kwargs): self.log.debug("Changing %s from '%s' to '%s' in environment for module command", key, old_value, new_value) + log_changes = kwargs.get('log_changes', True) cmd_list = self.compose_cmd_list(args) cmd = ' '.join(cmd_list) # note: module commands are always run in dry mode, and are kept hidden in trace and dry run output res = run_shell_cmd(cmd_list, env=environ, fail_on_error=False, use_bash=False, split_stderr=True, - hidden=True, in_dry_run=True, output_file=False) + hidden=True, in_dry_run=True, output_file=False, + log_output_on_success=log_changes) # stdout will contain python code (to change environment etc) # stderr will contain text (just like the normal module command) diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index aaa00a701b..3f1163f70a 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -360,7 +360,7 @@ def _answer_question(stdout, proc, qa_patterns, qa_wait_patterns): def run_shell_cmd(cmd, fail_on_error=True, split_stderr=False, stdin=None, env=None, hidden=False, in_dry_run=False, verbose_dry_run=False, work_dir=None, use_bash=True, output_file=True, stream_output=None, asynchronous=False, task_id=None, with_hooks=True, - qa_patterns=None, qa_wait_patterns=None, qa_timeout=100): + qa_patterns=None, qa_wait_patterns=None, qa_timeout=100, log_output_on_success=True): """ Run specified (interactive) shell command, and capture output + exit code. @@ -381,6 +381,7 @@ def run_shell_cmd(cmd, fail_on_error=True, split_stderr=False, stdin=None, env=N :param qa_patterns: list of 2-tuples with patterns for questions + corresponding answers :param qa_wait_patterns: list of strings with patterns for non-questions :param qa_timeout: amount of seconds to wait until more output is produced when there is no matching question + :param log_output_on_success: log output of command if it was successful :return: Named tuple with: - output: command output, stdout+stderr combined if split_stderr is disabled, only stdout otherwise @@ -604,18 +605,21 @@ def to_cmd_str(cmd): } run_hook(RUN_SHELL_CMD, hooks, post_step_hook=True, args=[cmd], kwargs=run_hook_kwargs) - # always log command output + # log command output (unless command was successful and log_output_on_success is disabled) cmd_name = cmd_str.split(' ')[0] if split_stderr: - _log.info(f"Output of '{cmd_name} ...' shell command (stdout only):\n{res.output}") - _log.info(f"Warnings and errors of '{cmd_name} ...' shell command (stderr only):\n{res.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}" else: - _log.info(f"Output of '{cmd_name} ...' shell command (stdout + stderr):\n{res.output}") + log_msg = f"Output of '{cmd_name} ...' shell command (stdout + stderr):\n{res.output}" if res.exit_code == EasyBuildExit.SUCCESS: - _log.info(f"Shell command completed successfully (see output above): {cmd_str}") + _log.info(f"Shell command 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}, see output above): {cmd_str}") + _log.warning(f"Shell command FAILED (exit code {res.exit_code}): {cmd_str}") + _log.info(log_msg) if fail_on_error: raise_run_shell_cmd_error(res) diff --git a/test/framework/run.py b/test/framework/run.py index a06e849a74..d3d869cc9c 100644 --- a/test/framework/run.py +++ b/test/framework/run.py @@ -448,9 +448,10 @@ def test_run_shell_cmd_log(self): os.close(fd) regex_start_cmd = re.compile("Running shell command 'echo hello' in /") - regex_cmd_exit = re.compile(r"Shell command completed successfully \(see output above\): echo hello") + 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) - # command output is always logged + # command output is logged init_logging(logfile, silent=True) with self.mocked_stdout_stderr(): res = run_shell_cmd("echo hello") @@ -460,6 +461,30 @@ def test_run_shell_cmd_log(self): logtxt = read_file(logfile) self.assertEqual(len(regex_start_cmd.findall(logtxt)), 1) self.assertEqual(len(regex_cmd_exit.findall(logtxt)), 1) + self.assertEqual(len(regex_cmd_output.findall(logtxt)), 1) + write_file(logfile, '') + + # command output can be suppressed + init_logging(logfile, silent=True) + with self.mocked_stdout_stderr(): + res = run_shell_cmd("echo hello", log_output_on_success=False) + stop_logging(logfile) + self.assertEqual(res.exit_code, 0) + self.assertEqual(res.output, 'hello\n') + logtxt = read_file(logfile) + self.assertEqual(len(regex_start_cmd.findall(logtxt)), 1) + self.assertEqual(len(regex_cmd_exit.findall(logtxt)), 1) + self.assertEqual(len(regex_cmd_output.findall(logtxt)), 0) + write_file(logfile, '') + # But is shown on error + init_logging(logfile, silent=True) + with self.mocked_stdout_stderr(): + res = run_shell_cmd("echo hello && false", log_output_on_success=False, fail_on_error=False) + stop_logging(logfile) + self.assertEqual(res.exit_code, 1) + self.assertEqual(res.output, 'hello\n') + logtxt = read_file(logfile) + self.assertEqual(len(regex_cmd_output.findall(logtxt)), 1) write_file(logfile, '') # with debugging enabled, exit code and output of command should only get logged once @@ -473,6 +498,7 @@ def test_run_shell_cmd_log(self): self.assertEqual(res.output, 'hello\n') self.assertEqual(len(regex_start_cmd.findall(read_file(logfile))), 1) self.assertEqual(len(regex_cmd_exit.findall(read_file(logfile))), 1) + self.assertEqual(len(regex_cmd_output.findall(read_file(logfile))), 1) write_file(logfile, '') def test_run_cmd_negative_exit_code(self):