Feature: Allow re-use of run_test() in install_time_test_callbacks (#26594)

Allow re-use of run_test() in install_time_test_callbacks

Co-authored-by: Greg Becker <becker33@llnl.gov>

lib/spack/spack/installer.py

@@ -561,6 +561,10 @@ def log(pkg):
     # Archive the environment modifications for the build.
     fs.install(pkg.env_mods_path, pkg.install_env_path)
 
+    # Archive the install-phase test log, if present
+    if pkg.test_install_log_path and os.path.exists(pkg.test_install_log_path):
+        fs.install(pkg.test_install_log_path, pkg.install_test_install_log_path)
+
     if os.path.exists(pkg.configure_args_path):
         # Archive the args used for the build
         fs.install(pkg.configure_args_path, pkg.install_configure_args_path)

lib/spack/spack/package.py

@@ -33,7 +33,7 @@
 
 import llnl.util.filesystem as fsys
 import llnl.util.tty as tty
-from llnl.util.lang import memoized
+from llnl.util.lang import memoized, nullcontext
 from llnl.util.link_tree import LinkTree
 
 import spack.compilers
@@ -77,6 +77,9 @@
 # Filename for the Spack build/install environment modifications file.
 _spack_build_envmodsfile = 'spack-build-env-mods.txt'
 
+# Filename for the Spack install phase-time test log.
+_spack_install_test_log = 'install-time-test-log.txt'
+
 # Filename of json with total build and phase times (seconds)
 _spack_times_log = 'install_times.json'
 
@@ -1244,6 +1247,16 @@ def configure_args_path(self):
         """Return the configure args file path associated with staging."""
         return os.path.join(self.stage.path, _spack_configure_argsfile)
 
+    @property
+    def test_install_log_path(self):
+        """Return the install phase-time test log file path, if set."""
+        return getattr(self, 'test_log_file', None)
+
+    @property
+    def install_test_install_log_path(self):
+        """Return the install location for the install phase-time test log."""
+        return fsys.join_path(self.metadata_dir, _spack_install_test_log)
+
     @property
     def times_log_path(self):
         """Return the times log json file."""
@@ -1916,6 +1929,33 @@ def cache_extra_test_sources(self, srcs):
                 fsys.mkdirp(os.path.dirname(dest_path))
                 fsys.copy(src_path, dest_path)
 
+    @contextlib.contextmanager
+    def _setup_test(self, verbose, externals):
+        self.test_failures = []
+        if self.test_suite:
+            self.test_log_file = self.test_suite.log_file_for_spec(self.spec)
+            self.tested_file = self.test_suite.tested_file_for_spec(self.spec)
+            pkg_id = self.test_suite.test_pkg_id(self.spec)
+        else:
+            self.test_log_file = fsys.join_path(
+                self.stage.path, _spack_install_test_log)
+            pkg_id = self.spec.format('{name}-{version}-{hash:7}')
+        fsys.touch(self.test_log_file)  # Otherwise log_parse complains
+
+        with tty.log.log_output(self.test_log_file, verbose) as logger:
+            with logger.force_echo():
+                tty.msg('Testing package {0}'.format(pkg_id))
+
+            # use debug print levels for log file to record commands
+            old_debug = tty.is_debug()
+            tty.set_debug(True)
+
+            try:
+                yield logger
+            finally:
+                # reset debug level
+                tty.set_debug(old_debug)
+
     def do_test(self, dirty=False, externals=False):
         if self.test_requires_compiler:
             compilers = spack.compilers.compilers_for_spec(
@@ -1927,19 +1967,14 @@ def do_test(self, dirty=False, externals=False):
                           self.spec.compiler)
                 return
 
-        # Clear test failures
-        self.test_failures = []
-        self.test_log_file = self.test_suite.log_file_for_spec(self.spec)
-        self.tested_file = self.test_suite.tested_file_for_spec(self.spec)
-        fsys.touch(self.test_log_file)  # Otherwise log_parse complains
-
         kwargs = {
             'dirty': dirty, 'fake': False, 'context': 'test',
             'externals': externals
         }
         if tty.is_verbose():
             kwargs['verbose'] = True
-        spack.build_environment.start_build_process(self, test_process, kwargs)
+        spack.build_environment.start_build_process(
+            self, test_process, kwargs)
 
     def test(self):
         # Defer tests to virtual and concrete packages
@@ -2684,45 +2719,54 @@ def rpath_args(self):
         """
         return " ".join("-Wl,-rpath,%s" % p for p in self.rpath)
 
+    def _run_test_callbacks(self, method_names, callback_type='install'):
+        """Tries to call all of the listed methods, returning immediately
+           if the list is None."""
+        if method_names is None:
+            return
+
+        fail_fast = spack.config.get('config:fail_fast', False)
+
+        with self._setup_test(verbose=False, externals=False) as logger:
+            # Report running each of the methods in the build log
+            print_test_message(
+                logger, 'Running {0}-time tests'.format(callback_type), True)
+
+            for name in method_names:
+                try:
+                    fn = getattr(self, name)
+
+                    msg = 'RUN-TESTS: {0}-time tests [{1}]' \
+                        .format(callback_type, name),
+                    print_test_message(logger, msg, True)
+
+                    fn()
+                except AttributeError as e:
+                    msg = 'RUN-TESTS: method not implemented [{0}]' \
+                        .format(name),
+                    print_test_message(logger, msg, True)
+
+                    self.test_failures.append((e, msg))
+                    if fail_fast:
+                        break
+
+            # Raise any collected failures here
+            if self.test_failures:
+                raise TestFailure(self.test_failures)
+
     @on_package_attributes(run_tests=True)
     def _run_default_build_time_test_callbacks(self):
         """Tries to call all the methods that are listed in the attribute
         ``build_time_test_callbacks`` if ``self.run_tests is True``.
-
-        If ``build_time_test_callbacks is None`` returns immediately.
         """
-        if self.build_time_test_callbacks is None:
-            return
-
-        for name in self.build_time_test_callbacks:
-            try:
-                fn = getattr(self, name)
-            except AttributeError:
-                msg = 'RUN-TESTS: method not implemented [{0}]'
-                tty.warn(msg.format(name))
-            else:
-                tty.msg('RUN-TESTS: build-time tests [{0}]'.format(name))
-                fn()
+        self._run_test_callbacks(self.build_time_test_callbacks, 'build')
 
     @on_package_attributes(run_tests=True)
     def _run_default_install_time_test_callbacks(self):
         """Tries to call all the methods that are listed in the attribute
         ``install_time_test_callbacks`` if ``self.run_tests is True``.
-
-        If ``install_time_test_callbacks is None`` returns immediately.
         """
-        if self.install_time_test_callbacks is None:
-            return
-
-        for name in self.install_time_test_callbacks:
-            try:
-                fn = getattr(self, name)
-            except AttributeError:
-                msg = 'RUN-TESTS: method not implemented [{0}]'
-                tty.warn(msg.format(name))
-            else:
-                tty.msg('RUN-TESTS: install-time tests [{0}]'.format(name))
-                fn()
+        self._run_test_callbacks(self.install_time_test_callbacks, 'install')
 
 
 def has_test_method(pkg):
@@ -2747,27 +2791,21 @@ def has_test_method(pkg):
 def print_test_message(logger, msg, verbose):
     if verbose:
         with logger.force_echo():
-            print(msg)
+            tty.msg(msg)
     else:
-        print(msg)
+        tty.msg(msg)
 
 
 def test_process(pkg, kwargs):
     verbose = kwargs.get('verbose', False)
     externals = kwargs.get('externals', False)
-    with tty.log.log_output(pkg.test_log_file, verbose) as logger:
-        with logger.force_echo():
-            tty.msg('Testing package {0}'
-                    .format(pkg.test_suite.test_pkg_id(pkg.spec)))
 
+    with pkg._setup_test(verbose, externals) as logger:
         if pkg.spec.external and not externals:
-            print_test_message(logger, 'Skipped external package', verbose)
+            print_test_message(
+                logger, 'Skipped tests for external package', verbose)
             return
 
-        # use debug print levels for log file to record commands
-        old_debug = tty.is_debug()
-        tty.set_debug(True)
-
         # run test methods from the package and all virtuals it
         # provides virtuals have to be deduped by name
         v_names = list(set([vspec.name
@@ -2786,8 +2824,7 @@ def test_process(pkg, kwargs):
 
         ran_actual_test_function = False
         try:
-            with fsys.working_dir(
-                    pkg.test_suite.test_dir_for_spec(pkg.spec)):
+            with fsys.working_dir(pkg.test_suite.test_dir_for_spec(pkg.spec)):
                 for spec in test_specs:
                     pkg.test_suite.current_test_spec = spec
                     # Fail gracefully if a virtual has no package/tests
@@ -2829,7 +2866,9 @@ def test_process(pkg, kwargs):
 
                     # Run the tests
                     ran_actual_test_function = True
-                    test_fn(pkg)
+                    context = logger.force_echo if verbose else nullcontext
+                    with context():
+                        test_fn(pkg)
 
             # If fail-fast was on, we error out above
             # If we collect errors, raise them in batch here
@@ -2837,15 +2876,12 @@ def test_process(pkg, kwargs):
                 raise TestFailure(pkg.test_failures)
 
         finally:
-            # reset debug level
-            tty.set_debug(old_debug)
-
             # flag the package as having been tested (i.e., ran one or more
             # non-pass-only methods
             if ran_actual_test_function:
                 fsys.touch(pkg.tested_file)
             else:
-                print_test_message(logger, 'No tests to run',  verbose)
+                print_test_message(logger, 'No tests to run', verbose)
 
 
 inject_flags = PackageBase.inject_flags

lib/spack/spack/test/cmd/install.py

@@ -1117,3 +1117,16 @@ def test_install_empty_env(tmpdir, mock_packages, mock_fetch,
     assert env_name in out
     assert 'environment' in out
     assert 'no specs to install' in out
+
+
+@pytest.mark.disable_clean_stage_check
+@pytest.mark.parametrize('name,method', [
+    ('test-build-callbacks', 'undefined-build-test'),
+    ('test-install-callbacks', 'undefined-install-test')
+])
+def test_install_callbacks_fail(install_mockery, mock_fetch, name, method):
+    output = install('--test=root', '--no-cache', name, fail_on_error=False)
+
+    assert output.count(method) == 2
+    assert output.count('method not implemented') == 1
+    assert output.count('TestFailure: 1 tests failed') == 1

lib/spack/spack/test/cmd/test.py

@@ -218,6 +218,8 @@ def test_test_list_all(mock_packages):
         "simple-standalone-test",
         "test-error",
         "test-fail",
+        "test-build-callbacks",
+        "test-install-callbacks"
     ])