Merge pull request #4321 from boegel/run_modules

implement support in `run` function for splitting stdout and stderr output + passing down environment to use, and switch to `run` function for running `module` commands

Author: ocaisa

easybuild/tools/modules.py

@@ -50,7 +50,7 @@
 from easybuild.tools.environment import ORIG_OS_ENVIRON, restore_env, setvar, unset_env_vars
 from easybuild.tools.filetools import convert_name, mkdir, normalize_path, path_matches, read_file, which, write_file
 from easybuild.tools.module_naming_scheme.mns import DEVEL_MODULE_SUFFIX
-from easybuild.tools.run import run_cmd, subprocess_popen_text
+from easybuild.tools.run import run
 from easybuild.tools.utilities import get_subclasses, nub
 
 # software root/version environment variable name prefixes
@@ -307,31 +307,32 @@ def check_module_function(self, allow_mismatch=False, regex=None):
         if self.testing:
             # grab 'module' function definition from environment if it's there; only during testing
             if 'module' in os.environ:
-                out, ec = os.environ['module'], 0
+                output, exit_code = os.environ['module'], 0
             else:
-                out, ec = None, 1
+                output, exit_code = None, 1
         else:
             cmd = "type module"
-            out, ec = run_cmd(cmd, simple=False, log_ok=False, log_all=False, force_in_dry_run=True, trace=False)
+            res = run(cmd, fail_on_error=False, in_dry_run=False, hidden=True)
+            output, exit_code = res.output, res.exit_code
 
         if regex is None:
             regex = r".*%s" % os.path.basename(self.cmd)
         mod_cmd_re = re.compile(regex, re.M)
         mod_details = "pattern '%s' (%s)" % (mod_cmd_re.pattern, self.NAME)
 
-        if ec == 0:
-            if mod_cmd_re.search(out):
+        if exit_code == 0:
+            if mod_cmd_re.search(output):
                 self.log.debug("Found pattern '%s' in defined 'module' function." % mod_cmd_re.pattern)
             else:
                 msg = "%s not found in defined 'module' function.\n" % mod_details
                 msg += "Specify the correct modules tool to avoid weird problems due to this mismatch, "
                 msg += "see the --modules-tool and --avail-modules-tools command line options.\n"
                 if allow_mismatch:
-                    msg += "Obtained definition of 'module' function: %s" % out
+                    msg += "Obtained definition of 'module' function: %s" % output
                     self.log.warning(msg)
                 else:
                     msg += "Or alternatively, use --allow-modules-tool-mismatch to stop treating this as an error. "
-                    msg += "Obtained definition of 'module' function: %s" % out
+                    msg += "Obtained definition of 'module' function: %s" % output
                     raise EasyBuildError(msg)
         else:
             # module function may not be defined (weird, but fine)
@@ -821,24 +822,23 @@ def run_module(self, *args, **kwargs):
                                key, old_value, new_value)
 
         cmd_list = self.compose_cmd_list(args)
-        full_cmd = ' '.join(cmd_list)
-        self.log.debug("Running module command '%s' from %s" % (full_cmd, os.getcwd()))
-
-        proc = subprocess_popen_text(cmd_list, env=environ)
+        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(cmd_list, env=environ, fail_on_error=False, shell=False, split_stderr=True,
+                  hidden=True, in_dry_run=True)
 
         # stdout will contain python code (to change environment etc)
         # stderr will contain text (just like the normal module command)
-        (stdout, stderr) = proc.communicate()
-        self.log.debug("Output of module command '%s': stdout: %s; stderr: %s" % (full_cmd, stdout, stderr))
+        stdout, stderr = res.output, res.stderr
+        self.log.debug("Output of module command '%s': stdout: %s; stderr: %s", cmd, stdout, stderr)
 
         # also catch and check exit code
-        exit_code = proc.returncode
-        if kwargs.get('check_exit_code', True) and exit_code != 0:
+        if kwargs.get('check_exit_code', True) and res.exit_code != 0:
             raise EasyBuildError("Module command '%s' failed with exit code %s; stderr: %s; stdout: %s",
-                                 ' '.join(cmd_list), exit_code, stderr, stdout)
+                                 cmd, res.exit_code, stderr, stdout)
 
         if kwargs.get('check_output', True):
-            self.check_module_output(full_cmd, stdout, stderr)
+            self.check_module_output(cmd, stdout, stderr)
 
         if kwargs.get('return_stderr', False):
             return stderr
@@ -1422,21 +1422,22 @@ def update(self):
 
         if build_option('update_modules_tool_cache'):
             spider_cmd = os.path.join(os.path.dirname(self.cmd), 'spider')
-            cmd = [spider_cmd, '-o', 'moduleT', os.environ['MODULEPATH']]
-            self.log.debug("Running command '%s'..." % ' '.join(cmd))
+            cmd_list = [spider_cmd, '-o', 'moduleT', os.environ['MODULEPATH']]
+            cmd = ' '.join(cmd_list)
+            self.log.debug("Running command '%s'...", cmd)
 
-            proc = subprocess_popen_text(cmd, env=os.environ)
-            (stdout, stderr) = proc.communicate()
+            res = run(cmd_list, env=os.environ, fail_on_error=False, shell=False, split_stderr=True, hidden=True)
+            stdout, stderr = res.output, res.stderr
 
             if stderr:
-                raise EasyBuildError("An error occurred when running '%s': %s", ' '.join(cmd), stderr)
+                raise EasyBuildError("An error occurred when running '%s': %s", cmd, stderr)
 
             if self.testing:
                 # don't actually update local cache when testing, just return the cache contents
                 return stdout
             else:
                 cache_fp = os.path.join(self.USER_CACHE_DIR, 'moduleT.lua')
-                self.log.debug("Updating Lmod spider cache %s with output from '%s'" % (cache_fp, ' '.join(cmd)))
+                self.log.debug("Updating Lmod spider cache %s with output from '%s'", cache_fp, cmd)
                 cache_dir = os.path.dirname(cache_fp)
                 if not os.path.exists(cache_dir):
                     mkdir(cache_dir, parents=True)

easybuild/tools/run.py

@@ -107,7 +107,7 @@ def cache_aware_func(cmd, *args, **kwargs):
 
 
 @run_cache
-def run(cmd, fail_on_error=True, split_stderr=False, stdin=None,
+def run(cmd, fail_on_error=True, split_stderr=False, stdin=None, env=None,
         hidden=False, in_dry_run=False, work_dir=None, shell=True,
         output_file=False, stream_output=False, asynchronous=False,
         qa_patterns=None, qa_wait_patterns=None):
@@ -117,6 +117,7 @@ def run(cmd, fail_on_error=True, split_stderr=False, stdin=None,
     :param fail_on_error: fail on non-zero exit code (enabled by default)
     :param split_stderr: split of stderr from stdout output
     :param stdin: input to be sent to stdin (nothing if set to None)
+    :param env: environment to use to run command (if None, inherit current process environment)
     :param hidden: do not show command in terminal output (when using --trace, or with --extended-dry-run / -x)
     :param in_dry_run: also run command in dry run mode
     :param work_dir: working directory to run command in (current working directory if None)
@@ -134,7 +135,7 @@ def run(cmd, fail_on_error=True, split_stderr=False, stdin=None,
     """
 
     # temporarily raise a NotImplementedError until all options are implemented
-    if any((split_stderr, work_dir, stream_output, asynchronous)):
+    if any((work_dir, stream_output, asynchronous)):
         raise NotImplementedError
 
     if qa_patterns or qa_wait_patterns:
@@ -163,7 +164,7 @@ def run(cmd, fail_on_error=True, split_stderr=False, stdin=None,
     if not in_dry_run and build_option('extended_dry_run'):
         if not hidden:
             silent = build_option('silent')
-            msg = f"  running command \"{cmd_msg}s\"\n"
+            msg = f"  running command \"{cmd_msg}\"\n"
             msg += f"  (in {work_dir})"
             dry_run_msg(msg, silent=silent)
 
@@ -179,21 +180,27 @@ def run(cmd, fail_on_error=True, split_stderr=False, stdin=None,
 
     # 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)
-    if shell:
-        executable = '/bin/bash'
-    else:
-        # stick to None (default value) when not running command via a shell
-        executable = None
+    # stick to None (default value) when not running command via a shell
+    executable = '/bin/bash' if shell else None
+
+    stderr = subprocess.PIPE if split_stderr else subprocess.STDOUT
 
     _log.info(f"Running command '{cmd_msg}' in {work_dir}")
-    proc = subprocess.run(cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, check=fail_on_error,
-                          input=stdin, shell=shell, executable=executable)
+    proc = subprocess.run(cmd, stdout=subprocess.PIPE, stderr=stderr, check=fail_on_error,
+                          env=env, input=stdin, shell=shell, executable=executable)
 
     # return output as a regular string rather than a byte sequence (and non-UTF-8 characters get stripped out)
     output = proc.stdout.decode('utf-8', 'ignore')
+    stderr_output = proc.stderr.decode('utf-8', 'ignore') if split_stderr else None
 
-    res = RunResult(output=output, exit_code=proc.returncode, stderr=None)
-    _log.info(f"Command '{cmd_msg}' exited with exit code {res.exit_code} and output:\n{res.output}")
+    res = RunResult(output=output, exit_code=proc.returncode, stderr=stderr_output)
+
+    if split_stderr:
+        log_msg = f"Command '{cmd_msg}' exited with exit code {res.exit_code}, "
+        log_msg += f"with stdout:\n{res.output}\nstderr:\n{res.stderr}"
+    else:
+        log_msg = f"Command '{cmd_msg}' exited with exit code {res.exit_code} and output:\n{res.output}"
+    _log.info(log_msg)
 
     if not hidden:
         time_since_start = time_str_since(start_time)

test/framework/modules.py

@@ -50,7 +50,7 @@
 from easybuild.tools.modules import EnvironmentModules, EnvironmentModulesC, EnvironmentModulesTcl, Lmod, NoModulesTool
 from easybuild.tools.modules import curr_module_paths, get_software_libdir, get_software_root, get_software_version
 from easybuild.tools.modules import invalidate_module_caches_for, modules_tool, reset_module_caches
-from easybuild.tools.run import run_cmd
+from easybuild.tools.run import run
 
 
 # number of modules included for testing purposes
@@ -191,6 +191,21 @@ def test_run_module(self):
         regex = re.compile(r'^os\.environ\[', re.M)
         self.assertFalse(regex.search(out), "Pattern '%s' should not be found in: %s" % (regex.pattern, out))
 
+    def test_list(self):
+        """
+        Test running 'module list' via ModulesTool instance.
+        """
+        # make very sure no modules are currently loaded
+        self.modtool.run_module('purge', '--force')
+
+        out = self.modtool.list()
+        self.assertEqual(out, [])
+
+        mods = ['GCC/7.3.0-2.30']
+        self.modtool.load(mods)
+        out = self.modtool.list()
+        self.assertEqual([x['mod_name'] for x in out], mods)
+
     def test_avail(self):
         """Test if getting a (restricted) list of available modules works."""
         self.init_testmods()
@@ -1317,9 +1332,9 @@ def test_module_use_bash(self):
         self.assertIn(modules_dir, modulepath)
 
         with self.mocked_stdout_stderr():
-            out, _ = run_cmd("bash -c 'echo MODULEPATH: $MODULEPATH'", simple=False)
-        self.assertEqual(out.strip(), "MODULEPATH: %s" % modulepath)
-        self.assertIn(modules_dir, out)
+            res = run("bash -c 'echo MODULEPATH: $MODULEPATH'")
+        self.assertEqual(res.output.strip(), f"MODULEPATH: {modulepath}")
+        self.assertIn(modules_dir, res.output)
 
     def test_load_in_hierarchy(self):
         """Test whether loading a module in a module hierarchy results in loading the correct module."""

test/framework/run.py

@@ -369,6 +369,28 @@ def test_run_cmd_log_output(self):
             self.assertTrue(out.startswith('foo ') and out.endswith(' bar'))
             self.assertEqual(type(out), str)
 
+    def test_run_split_stderr(self):
+        """Test getting split stdout/stderr output from run function."""
+        cmd = ';'.join([
+            "echo ok",
+            "echo warning >&2",
+        ])
+
+        # by default, output contains both stdout + stderr
+        with self.mocked_stdout_stderr():
+            res = run(cmd)
+        self.assertEqual(res.exit_code, 0)
+        output_lines = res.output.split('\n')
+        self.assertTrue("ok" in output_lines)
+        self.assertTrue("warning" in output_lines)
+        self.assertEqual(res.stderr, None)
+
+        with self.mocked_stdout_stderr():
+            res = run(cmd, split_stderr=True)
+        self.assertEqual(res.exit_code, 0)
+        self.assertEqual(res.stderr, "warning\n")
+        self.assertEqual(res.output, "ok\n")
+
     def test_run_cmd_trace(self):
         """Test run_cmd in trace mode, and with tracing disabled."""
 
@@ -778,55 +800,96 @@ def test_parse_log_error(self):
         errors = parse_log_for_error("error failed", True)
         self.assertEqual(len(errors), 1)
 
-    def test_dry_run(self):
-        """Test use of functions under (extended) dry run."""
+    def test_run_cmd_dry_run(self):
+        """Test use of run_cmd function under (extended) dry run."""
         build_options = {
             'extended_dry_run': True,
             'silent': False,
         }
         init_config(build_options=build_options)
 
+        cmd = "somecommand foo 123 bar"
+
         self.mock_stdout(True)
-        run_cmd("somecommand foo 123 bar")
-        txt = self.get_stdout()
+        run_cmd(cmd)
+        stdout = self.get_stdout()
         self.mock_stdout(False)
 
         expected = """  running command "somecommand foo 123 bar"\n"""
-        self.assertIn(expected, txt)
+        self.assertIn(expected, stdout)
 
         # check disabling 'verbose'
         self.mock_stdout(True)
         run_cmd("somecommand foo 123 bar", verbose=False)
+        stdout = self.get_stdout()
         self.mock_stdout(False)
+        self.assertNotIn(expected, stdout)
 
         # check forced run_cmd
         outfile = os.path.join(self.test_prefix, 'cmd.out')
         self.assertNotExists(outfile)
         self.mock_stdout(True)
         run_cmd("echo 'This is always echoed' > %s" % outfile, force_in_dry_run=True)
-        txt = self.get_stdout()
         self.mock_stdout(False)
         self.assertExists(outfile)
         self.assertEqual(read_file(outfile), "This is always echoed\n")
 
-        write_file(outfile, '', forced=True)
+        # Q&A commands
+        self.mock_stdout(True)
+        run_cmd_qa("some_qa_cmd", {'question1': 'answer1'})
+        stdout = self.get_stdout()
+        self.mock_stdout(False)
+
+        expected = """  running interactive command "some_qa_cmd"\n"""
+        self.assertIn(expected, stdout)
+
+    def test_run_dry_run(self):
+        """Test use of run function under (extended) dry run."""
+        build_options = {
+            'extended_dry_run': True,
+            'silent': False,
+        }
+        init_config(build_options=build_options)
+
+        cmd = "somecommand foo 123 bar"
 
-        # check forced run
         self.mock_stdout(True)
-        run("echo 'This is always echoed' > %s" % outfile, in_dry_run=True)
-        txt = self.get_stdout()
+        res = run(cmd)
+        stdout = self.get_stdout()
         self.mock_stdout(False)
-        self.assertExists(outfile)
-        self.assertEqual(read_file(outfile), "This is always echoed\n")
+        # fake output/exit code is returned for commands not actually run in dry run mode
+        self.assertEqual(res.exit_code, 0)
+        self.assertEqual(res.output, '')
+        self.assertEqual(res.stderr, None)
+        # check dry run output
+        expected = """  running command "somecommand foo 123 bar"\n"""
+        self.assertIn(expected, stdout)
 
-        # Q&A commands
+        # check enabling 'hidden'
         self.mock_stdout(True)
-        run_cmd_qa("some_qa_cmd", {'question1': 'answer1'})
-        txt = self.get_stdout()
+        res = run(cmd, hidden=True)
+        stdout = self.get_stdout()
         self.mock_stdout(False)
+        # fake output/exit code is returned for commands not actually run in dry run mode
+        self.assertEqual(res.exit_code, 0)
+        self.assertEqual(res.output, '')
+        self.assertEqual(res.stderr, None)
+        # dry run output should be missing
+        self.assertNotIn(expected, stdout)
 
-        expected = """  running interactive command "some_qa_cmd"\n"""
-        self.assertIn(expected, txt)
+        # check forced run_cmd
+        outfile = os.path.join(self.test_prefix, 'cmd.out')
+        self.assertNotExists(outfile)
+        self.mock_stdout(True)
+        res = run("echo 'This is always echoed' > %s; echo done; false" % outfile, fail_on_error=False, in_dry_run=True)
+        stdout = self.get_stdout()
+        self.mock_stdout(False)
+        self.assertNotIn('running command "', stdout)
+        self.assertNotEqual(res.exit_code, 0)
+        self.assertEqual(res.output, 'done\n')
+        self.assertEqual(res.stderr, None)
+        self.assertExists(outfile)
+        self.assertEqual(read_file(outfile), "This is always echoed\n")
 
     def test_run_cmd_list(self):
         """Test run_cmd with command specified as a list rather than a string"""