SPACK-69: spack install now logs build output to install directory.

- spack install suppresses build output by default.
  - use install -v to show build output on the console too

- package.py uses log_output context to redirect output and log it to a file
  - filters color codes out of output written to file
  - optionally echos to the terminal

- YAML directory layout knows about its build log.
  - can get path to install build log to from directory layout
  - Package.install now copies the build log to $prefix/.spack/build.out

- Error message from failed install execution now includes build log location

lib/spack/spack/cmd/install.py

@@ -47,6 +47,9 @@ def setup_parser(subparser):
     subparser.add_argument(
         '-n', '--no-checksum', action='store_true', dest='no_checksum',
         help="Do not check packages against checksum")
+    subparser.add_argument(
+        '-v', '--verbose', action='store_true', dest='verbose',
+        help="Display verbose build output while installing.")
     subparser.add_argument(
         '--fake', action='store_true', dest='fake',
         help="Fake install.  Just remove the prefix and touch a fake file in it.")
@@ -73,4 +76,5 @@ def install(parser, args):
             keep_stage=args.keep_stage,
             ignore_deps=args.ignore_deps,
             make_jobs=args.jobs,
+            verbose=args.verbose,
             fake=args.fake)

lib/spack/spack/directory_layout.py

@@ -35,7 +35,6 @@
 from llnl.util.lang import memoized
 from llnl.util.filesystem import join_path, mkdirp
 
-import spack
 from spack.spec import Spec
 from spack.error import SpackError
 
@@ -175,6 +174,7 @@ def __init__(self, root, **kwargs):
 
         self.spec_file_name      = 'spec.yaml'
         self.extension_file_name = 'extensions.yaml'
+        self.build_log_name      = 'build.out' # TODO: use config file.
 
         # Cache of already written/read extension maps.
         self._extension_maps = {}
@@ -233,6 +233,11 @@ def metadata_path(self, spec):
         return join_path(self.path_for_spec(spec), self.metadata_dir)
 
 
+    def build_log_path(self, spec):
+        return join_path(self.path_for_spec(spec), self.metadata_dir,
+                         self.build_log_name)
+
+
     def create_install_directory(self, spec):
         _check_concrete(spec)
 

lib/spack/spack/error.py

@@ -30,7 +30,12 @@ class SpackError(Exception):
     def __init__(self, message, long_message=None):
         super(SpackError, self).__init__()
         self.message = message
-        self.long_message = long_message
+        self._long_message = long_message
+
+
+    @property
+    def long_message(self):
+        return self._long_message
 
 
     def __str__(self):

lib/spack/spack/package.py

@@ -36,7 +36,7 @@
 import os
 import re
 import time
-import inspect
+import itertools
 import subprocess
 import platform as py_platform
 import multiprocessing
@@ -45,6 +45,7 @@
 from StringIO import StringIO
 
 import llnl.util.tty as tty
+from llnl.util.tty.log import log_output
 from llnl.util.link_tree import LinkTree
 from llnl.util.filesystem import *
 from llnl.util.lang import *
@@ -55,12 +56,12 @@
 import spack.mirror
 import spack.hooks
 import spack.directives
-import spack.build_environment as build_env
+import spack.build_environment
-import spack.url as url
+import spack.url
+import spack.util.web
 import spack.fetch_strategy as fs
 from spack.version import *
 from spack.stage import Stage
-from spack.util.web import get_pages
 from spack.util.compression import allowed_archive, extension
 from spack.util.executable import ProcessError
 
@@ -427,8 +428,8 @@ def url_for_version(self, version):
             return version_urls[version]
 
         # If we have no idea, try to substitute the version.
-        return url.substitute_version(self.nearest_url(version),
+        return spack.url.substitute_version(self.nearest_url(version),
-                                      self.url_version(version))
+                                            self.url_version(version))
 
 
     @property
@@ -711,20 +712,28 @@ def do_fake_install(self):
         mkdirp(self.prefix.man1)
 
 
-    def do_install(self, **kwargs):
+    def _build_logger(self, log_path):
-        """This class should call this version of the install method.
+        """Create a context manager to log build output."""
-           Package implementations should override install().
+
+
+
+    def do_install(self,
+                   keep_prefix=False,  keep_stage=False, ignore_deps=False,
+                   skip_patch=False, verbose=False, make_jobs=None, fake=False):
+        """Called by commands to install a package and its dependencies.
+
+        Package implementations should override install() to describe
+        their build process.
+
+        Args:
+        keep_prefix -- Keep install prefix on failure. By default, destroys it.
+        keep_stage  -- Keep stage on successful build. By default, destroys it.
+        ignore_deps -- Do not install dependencies before installing this package.
+        fake        -- Don't really build -- install fake stub files instead.
+        skip_patch  -- Skip patch stage of build if True.
+        verbose     -- Display verbose build output (by default, suppresses it)
+        make_jobs   -- Number of make jobs to use for install.  Default is ncpus.
         """
-        # whether to keep the prefix on failure.  Default is to destroy it.
-        keep_prefix  = kwargs.get('keep_prefix', False)
-        keep_stage   = kwargs.get('keep_stage',  False)
-        ignore_deps  = kwargs.get('ignore_deps', False)
-        fake_install = kwargs.get('fake',        False)
-        skip_patch   = kwargs.get('skip_patch',  False)
-
-        # Override builtin number of make jobs.
-        self.make_jobs    = kwargs.get('make_jobs',   None)
-
         if not self.spec.concrete:
             raise ValueError("Can only install concrete packages.")
 
@@ -735,10 +744,13 @@ def do_install(self, **kwargs):
         tty.msg("Installing %s" % self.name)
 
         if not ignore_deps:
-            self.do_install_dependencies(**kwargs)
+            self.do_install_dependencies(
+                keep_prefix=keep_prefix, keep_stage=keep_stage, ignore_deps=ignore_deps,
+                fake=fake, skip_patch=skip_patch, verbose=verbose,
+                make_jobs=make_jobs)
 
         start_time = time.time()
-        if not fake_install:
+        if not fake:
             if not skip_patch:
                 self.do_patch()
             else:
@@ -768,16 +780,26 @@ def real_work():
                 spack.hooks.pre_install(self)
 
                 # Set up process's build environment before running install.
-                if fake_install:
+                if fake:
                     self.do_fake_install()
                 else:
-                    # Subclasses implement install() to do the real work.
+                    # Do the real install in the source directory.
                     self.stage.chdir_to_source()
-                    self.install(self.spec, self.prefix)
+
+                    # This redirects I/O to a build log (and optionally to the terminal)
+                    log_path = join_path(os.getcwd(), 'spack-build.out')
+                    log_file = open(log_path, 'w')
+                    with log_output(log_file, verbose, sys.stdout.isatty(), True):
+                        self.install(self.spec, self.prefix)
 
                 # Ensure that something was actually installed.
                 self._sanity_check_install()
 
+                # Move build log into install directory on success
+                if not fake:
+                    log_install_path = spack.install_layout.build_log_path(self.spec)
+                    install(log_path, log_install_path)
+
                 # On successful install, remove the stage.
                 if not keep_stage:
                     self.stage.destroy()
@@ -792,6 +814,9 @@ def real_work():
                 print_pkg(self.prefix)
 
             except ProcessError, e:
+                # Annotate with location of build log.
+                e.build_log = log_path
+
                 # One of the processes returned an error code.
                 # Suppress detailed stack trace here unless in debug mode
                 if spack.debug:
@@ -808,7 +833,7 @@ def real_work():
                 cleanup()
                 raise
 
-        build_env.fork(self, real_work)
+        spack.build_environment.fork(self, real_work)
 
         # Once everything else is done, run post install hooks
         spack.hooks.post_install(self)
@@ -868,9 +893,7 @@ def install(self, spec, prefix):
         raise InstallError("Package %s provides no install method!" % self.name)
 
 
-    def do_uninstall(self, **kwargs):
+    def do_uninstall(self, force=False):
-        force = kwargs.get('force', False)
-
         if not self.installed:
             raise InstallError(str(self.spec) + " is not installed.")
 
@@ -913,14 +936,13 @@ def _sanity_check_extension(self):
             raise ActivationError("%s does not extend %s!" % (self.name, self.extendee.name))
 
 
-    def do_activate(self, **kwargs):
+    def do_activate(self, force=False):
         """Called on an etension to invoke the extendee's activate method.
 
         Commands should call this routine, and should not call
         activate() directly.
         """
         self._sanity_check_extension()
-        force = kwargs.get('force', False)
 
         spack.install_layout.check_extension_conflict(
             self.extendee_spec, self.spec)
@@ -930,7 +952,7 @@ def do_activate(self, **kwargs):
             for spec in self.spec.traverse(root=False):
                 if spec.package.extends(self.extendee_spec):
                     if not spec.package.activated:
-                        spec.package.do_activate(**kwargs)
+                        spec.package.do_activate(force=force)
 
         self.extendee_spec.package.activate(self, **self.extendee_args)
 
@@ -1084,12 +1106,13 @@ def find_versions_of_archive(*archive_urls, **kwargs):
     if list_url:
         list_urls.add(list_url)
     for aurl in archive_urls:
-        list_urls.add(url.find_list_url(aurl))
+        list_urls.add(spack.url.find_list_url(aurl))
 
     # Grab some web pages to scrape.
     page_map = {}
     for lurl in list_urls:
-        page_map.update(get_pages(lurl, depth=list_depth))
+        pages = spack.util.web.get_pages(lurl, depth=list_depth)
+        page_map.update(pages)
 
     # Scrape them for archive URLs
     regexes = []
@@ -1098,7 +1121,7 @@ def find_versions_of_archive(*archive_urls, **kwargs):
         # the version part of the URL.  The capture group is converted
         # to a generic wildcard, so we can use this to extract things
         # on a page that look like archive URLs.
-        url_regex = url.wildcard_version(aurl)
+        url_regex = spack.url.wildcard_version(aurl)
 
         # We'll be a bit more liberal and just look for the archive
         # part, not the full path.

lib/spack/spack/util/executable.py

@@ -143,27 +143,72 @@ def which(name, **kwargs):
 
 
 class ProcessError(spack.error.SpackError):
-    def __init__(self, msg, long_msg=None):
+    def __init__(self, msg, long_message=None):
-        # Friendlier exception trace info for failed executables
+        # These are used for detailed debugging information for
-        long_msg = long_msg + "\n" if long_msg else ""
+        # package builds.  They're built up gradually as the exception
-        for f in inspect.stack():
+        # propagates.
-            frame = f[0]
+        self.package_context = _get_package_context()
-            loc = frame.f_locals
+        self.build_log = None
-            if 'self' in loc:
-                obj = loc['self']
-                if isinstance(obj, spack.Package):
-                    long_msg += "---\n"
-                    long_msg += "Context:\n"
-                    long_msg += "  %s:%d, in %s:\n" % (
-                        inspect.getfile(frame.f_code),
-                        frame.f_lineno,
-                        frame.f_code.co_name)
 
-                    lines, start = inspect.getsourcelines(frame)
+        super(ProcessError, self).__init__(msg, long_message)
-                    for i, line in enumerate(lines):
-                        mark = ">> " if start + i == frame.f_lineno else "   "
-                        long_msg += "  %s%-5d%s\n" % (
-                            mark, start + i, line.rstrip())
-                    break
 
-        super(ProcessError, self).__init__(msg, long_msg)
+    @property
+    def long_message(self):
+        msg = self._long_message
+        if msg: msg += "\n\n"
+
+        if self.build_log:
+            msg += "See build log for details:\n"
+            msg += "  %s" % self.build_log
+
+        if self.package_context:
+            if msg: msg += "\n\n"
+            msg += '\n'.join(self.package_context)
+
+        return msg
+
+
+def _get_package_context():
+    """Return some context for an error message when the build fails.
+
+    This should be called within a ProcessError when the exception is
+    thrown.
+
+    Args:
+    process_error -- A ProcessError raised during install()
+
+    This function inspects the stack to find where we failed in the
+    package file, and it adds detailed context to the long_message
+    from there.
+
+    """
+    lines = []
+
+    # Walk up the stack
+    for f in inspect.stack():
+        frame = f[0]
+
+        # Find a frame with 'self' in the local variables.
+        if not 'self' in frame.f_locals:
+            continue
+
+        # Look only at a frame in a subclass of spack.Package
+        obj = frame.f_locals['self']
+        if type(obj) != spack.Package and isinstance(obj, spack.Package):
+            break
+    else:
+        # Didn't find anything
+        return lines
+
+    # Build a message showing where in install we failed.
+    lines.append("%s:%d, in %s:" % (
+        inspect.getfile(frame.f_code),
+        frame.f_lineno,
+        frame.f_code.co_name))
+
+    sourcelines, start = inspect.getsourcelines(frame)
+    for i, line in enumerate(sourcelines):
+        mark = ">> " if start + i == frame.f_lineno else "   "
+        lines.append("  %s%-5d%s" % (mark, start + i, line.rstrip()))
+
+    return lines