Skip to content

Don't log variables (un)set + raw output of module command when cleaning up fake module #4942

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
boegel merged 5 commits into from
Sep 8, 2025
Merged

Don't log variables (un)set + raw output of module command when cleaning up fake module #4942

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
45ce358
Add option to hide output of successful shell commands
Flamefire Jun 27, 2025
f0c0a31
Don't log variables (un)set when cleaning up fake module
Flamefire Jun 27, 2025
7f388df
Adapt and extend test
Flamefire Jun 27, 2025
61d9436
Merge branch 'easybuilders:develop' into silent-fake-module-cleanup
Flamefire Aug 13, 2025
361c1ef
rename log subpression options for `run_shell_cmd` and `ModulesTool.r…
boegel Sep 4, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 3 additions & 2 deletions easybuild/framework/easyblock.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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], silent=True)
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:
Expand All @@ -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."""
Expand Down
22 changes: 12 additions & 10 deletions easybuild/tools/environment.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -76,12 +76,13 @@ def get_changes():
return _changes


def setvar(key, value, verbose=True):
def setvar(key, value, verbose=True, log_changes=True):

@lexming lexming Jul 29, 2025

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

can we use the existing verbose for this? something like

if verbose:
    <print log>
if verbose and dry_run:
    <do the existing dry run prints>

@Flamefire Flamefire Jul 30, 2025

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

verbose is currently solely used for the extended-dry-run and I wasn't sure of the impact.

My new idea would be:

if verbose or debug-option: Print setting
Set verbose=False for all module command uses and the fake module unset.
Also only log output of module commands (lmod calls) when debug-option is set

The changes by the module commands are usually not interesting and just make the log harder to read. So suppressing them by default but with an option to show them sounds like the most sensible approach.

@Flamefire Flamefire Jul 30, 2025

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually at least the reports from boegelbot runs include the debug flag so that wouldn't make those reports more readable :-/

@lexming lexming Jul 30, 2025

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Given the limited length of the failed report, we can very well disable debug in the bot. Most of the time debug logs are useless when a build fails anyhow, in that case you just need the output of the failing command/test/sanity check. We can discuss about this in the next call.

@Flamefire Flamefire Jul 30, 2025

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So shall we go forward with my proposal above or wait for the call too?

@boegel boegel Sep 3, 2025

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I strongly prefer keeping debug enabled in the bot, since it does result in a better log (though less easy to parse).

I think selectively making setvar log less as is being done here makes sense.

@Flamefire Flamefire Sep 4, 2025

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd want to make a more general decision here. Basically what we usually don't want is output from a) module commands (proposed, not yet implemented) b) variables set by loading modules c) variables changed by unloading modules, especially the fake/real-module in the sanity check

That information might still be useful in limited contexts, e.g. during debugging strange failures, so logging it with --debug sounds reasonable as otherwise there won't be any way to show those.

But if those information is shown with --debug and the test reports use --debug we haven't gained anything for that common use case.
How do we address this?

We could introduce debug levels, similar to how -vv is more verbose than -v in other programs.
Or we could use --debug --trace as "log more debug info"

@boegel boegel Sep 8, 2025

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We have an extra level of logging (--devel), we could only log those details when devel log level is used?

@boegel boegel Sep 8, 2025

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

BTW, we're sort of discussing this in the wrong place.

I'm about to merge this PR, and discussing stuff in closed PRs is something we should definitely avoid...

@Flamefire Can you open an issue to follow-up on this, beyond the changes made in this PR?

"""
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]
Expand All @@ -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)
Expand Down Expand Up @@ -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:
Expand All @@ -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():
Expand Down
12 changes: 7 additions & 5 deletions easybuild/tools/modules.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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, silent=False):
"""
Unload all requested modules.
"""
for mod in modules:
self.run_module('unload', mod)
self.run_module('unload', mod, silent=silent)

def purge(self):
"""
Expand Down Expand Up @@ -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, silent=False):
Comment thread
Flamefire marked this conversation as resolved.
Outdated
"""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=not silent)

def check_module_output(self, cmd, stdout, stderr):
"""Check output of 'module' command, see if if is potentially invalid."""
Expand Down Expand Up @@ -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)

silent = kwargs.get('silent', False)
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,
hide_output_on_success=silent)

# stdout will contain python code (to change environment etc)
# stderr will contain text (just like the normal module command)
Expand Down
15 changes: 9 additions & 6 deletions easybuild/tools/run.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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, hide_output_on_success=False):
Comment thread
Flamefire marked this conversation as resolved.
Outdated
"""
Run specified (interactive) shell command, and capture output + exit code.

Expand Down Expand Up @@ -607,15 +607,18 @@ def to_cmd_str(cmd):
# always log command output
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"
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 not hide_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)

Expand Down
30 changes: 28 additions & 2 deletions test/framework/run.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Expand All @@ -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", hide_output_on_success=True)
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", hide_output_on_success=True, 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
Expand All @@ -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):
Expand Down