adding phase level log files

Signed-off-by: vsoch <vsoch@users.noreply.github.com>

lib/spack/llnl/util/tty/log.py

@@ -434,16 +434,15 @@ class log_output(object):
     """
 
     def __init__(self, file_like=None, echo=False, debug=0, buffer=False,
-                 env=None, phase=None):
+                 env=None):
         """Create a new output log context manager.
 
         Args:
             file_like (str or stream): open file object or name of file where
                 output should be logged
-            echo (bool): whether to echo output in addition to logging it
-            debug (int): positive to enable tty debug mode during logging
-            phase (str): the name of the phase, to eventually help organize
-            buffer (bool): pass buffer=True to skip unbuffering output; note
+            echo     (bool): whether to echo output in addition to logging it
+            debug    (int): positive to enable tty debug mode during logging
+            buffer   (bool): pass buffer=True to skip unbuffering output; note
                 this doesn't set up any *new* buffering
 
         log_output can take either a file object or a filename. If a
@@ -466,7 +465,6 @@ def __init__(self, file_like=None, echo=False, debug=0, buffer=False,
         self.env = env  # the environment to use for _writer_daemon
 
         self._active = False  # used to prevent re-entry
-        self._phase = phase
 
     def __call__(self, file_like=None, echo=None, debug=None, buffer=None):
         """This behaves the same as init. It allows a logger to be reused.

lib/spack/spack/installer.py

@@ -522,6 +522,12 @@ def log(pkg):
     # Archive the whole stdout + stderr for the package
     fs.install(pkg.log_path, pkg.install_log_path)
 
+    # Archive all phase log paths
+    for phase_log in pkg.phase_log_files:
+        log_file = os.path.basename(phase_log)
+        log_file = os.path.join(os.path.dirname(packages_dir), log_file)
+        fs.install(phase_log, log_file)
+
     # Archive the environment used for the build
     fs.install(pkg.env_path, pkg.install_env_path)
 
@@ -573,6 +579,21 @@ def log(pkg):
     dump_packages(pkg.spec, packages_dir)
 
 
+def combine_phase_logs(pkg):
+    """
+    Each phase will produce it's own log, so this function aims to cat all the
+    separate phase log output files into the pkg.log_path.
+
+    Args:
+        pkg (Package): the package that was built and installed
+    """
+    log_files = pkg.phase_log_files
+
+    with open(pkg.log_path, 'w') as fd:
+        for line in itertools.chain.from_iterable(list(map(open, log_files))):
+            fd.write(line)
+
+
 def package_id(pkg):
     """A "unique" package identifier for installation purposes
 
@@ -1746,10 +1767,17 @@ def build_process(pkg, kwargs):
 
                 # Spawn a daemon that reads from a pipe and redirects
                 # everything to log_path, and provide the phase for logging
-                for phase_name, phase_attr in zip(
-                        pkg.phases, pkg._InstallPhase_phases):
+                for i, (phase_name, phase_attr) in enumerate(zip(
+                        pkg.phases, pkg._InstallPhase_phases)):
+
+                    # Keep a log file for each phase
+                    log_dir = os.path.dirname(pkg.log_path)
+                    log_file = "spack-build-%02d-%s-out.txt" % (
+                        i + 1, phase_name.lower()
+                    )
+                    log_file = os.path.join(log_dir, log_file)
 
-                    with log_output(pkg.log_path, echo, True, phase=phase_name,
+                    with log_output(log_file, echo, True,
                                     env=unmodified_env) as logger:
 
                         with logger.force_echo():
@@ -1761,12 +1789,25 @@ def build_process(pkg, kwargs):
 
                         # Redirect stdout and stderr to daemon pipe
                         phase = getattr(pkg, phase_attr)
-                        phase(pkg.spec, pkg.prefix)
+
+                        # Catch any errors to report to logging
+                        try:
+                            phase(pkg.spec, pkg.prefix)
+                            if monitor:
+                                monitor.send_phase(pkg, phase_name, log_file, "SUCCESS")
+
+                        except Exception:
+                            combine_phase_logs(pkg)
+                            # This needs to be tested
+                            # TODO: Add BuildPhase model with output and error
+                            # statuses should be for phases
+                            if monitor:
+                                monitor.send_phase(pkg, phase_name, log_file, "ERROR")
 
             # After log, we can get all output/error files from the package stage
             echo = logger.echo
+            combine_phase_logs(pkg)
             log(pkg)
-            # monitor.
 
         # Run post install hooks before build stage is removed.
         spack.hooks.post_install(pkg.spec)
@@ -1781,14 +1822,9 @@ def build_process(pkg, kwargs):
                     _hms(pkg._total_time)))
     _print_installed_pkg(pkg.prefix)
 
-    # Update that the task was succcessful, parse metadata folder
+    # Send final metadata (environment, etc.)
     if monitor:
-        monitor.update_task(pkg.spec, "SUCCESS")
-
-        # Parse final output and metadata from package directory
-        full_hash = pkg.spec.full_hash()
-        package_dir = spack.store.layout.build_packages_path(pkg.spec)
-        monitor.send_package_metadata(full_hash, os.path.dirname(package_dir))
+        monitor.send_final(pkg)
 
     # preserve verbosity across runs
     return echo

lib/spack/spack/monitor.py

@@ -17,6 +17,7 @@
 
 import spack
 import spack.hash_types as ht
+import spack.store
 import llnl.util.tty as tty
 from copy import deepcopy
 
@@ -271,9 +272,9 @@ def cancel_task(self, spec):
         # data = {current_package: "FAILED", main_package: "CANCELLED"}
         # return self.do_request("tasks/update/", data=json.dumps(data))
 
-    def send_package_metadata(self, full_hash, meta_dir):
+    def send_final(self, pkg):
         """Given a metadata folder, usually .spack within the spack root
-        opt/<system>/<compiler>/<package>/.spack with (maximally) the following:
+        opt/<system>/<compiler>/<package>/.spack with the following:
 
              'spack-configure-args.txt',
              'spack-build-env.txt',
@@ -283,13 +284,11 @@ def send_package_metadata(self, full_hash, meta_dir):
              'install_manifest.json',
              'repos'
 
-        read in the environment, and output and (if they exist, error) files
-        and send to the monitor server. full_hash should be the full_hash for
-        the package in question, and meta_dir should be the .spack folder
-        mentioned above.
+        read in all metadata files except for phase and output (which are sent
+        as they are generated) and send to the monitor server.
         """
+        meta_dir = os.path.dirname(pkg.install_log_path)
         errors_file = os.path.join(meta_dir, "errors.txt")
-        output_file = os.path.join(meta_dir, "spack-build-out.txt")
         env_file = os.path.join(meta_dir, "spack-build-env.txt")
         config_file = os.path.join(meta_dir, "spack-configure-args.txt")
         manifest_file = os.path.join(meta_dir, "install_manifest.json")
@@ -299,12 +298,24 @@ def send_package_metadata(self, full_hash, meta_dir):
         data = {"environ": self._read_environment_file(env_file),
                 "config": read_file(config_file),
                 "manifest": read_json(manifest_file),
-                "output": read_file(output_file),
                 "errors": read_file(errors_file),
-                "full_hash": full_hash}
+                "full_hash": pkg.spec.full_hash()}
 
         return self.do_request("packages/metadata/", data=json.dumps(data))
 
+    def send_phase(self, pkg, phase_name, phase_output_file, status):
+        """Given a package, phase name, and status, update the monitor endpoint
+        to alert of the status of the stage. This includes parsing the package
+        metadata folder for phase output and error files
+        """
+        # Send output specific to the phase (does this include error?)
+        data = {"status": status,
+                "output": read_file(phase_output_file),
+                "full_hash": pkg.spec.full_hash()}
+
+        # TODO: Spack Monitor needs this endpoint added
+        return self.do_request("phases/metadata/", data=json.dumps(data))
+
     def _read_environment_file(self, filename):
         """Given an environment file, we want to read it, split by semicolons
         and new lines, and then parse down to the subset of SPACK_* variables.

lib/spack/spack/package.py

@@ -15,6 +15,7 @@
 import contextlib
 import copy
 import functools
+import glob
 import hashlib
 import inspect
 import os
@@ -1066,6 +1067,13 @@ def log_path(self):
         # Otherwise, return the current log path name.
         return os.path.join(self.stage.path, _spack_build_logfile)
 
+    @property
+    def phase_log_files(self):
+        """Find sorted phase log files written to the staging directory"""
+        log_files = glob.glob("%s/spack-build-*-out.txt" % self.stage.path)
+        log_files.sort()
+        return log_files
+
     @property
     def install_log_path(self):
         """Return the build log file path on successful installation."""