Fix SPACK-69: Merge branch 'features/build-logging' into develop

lib/spack/llnl/util/filesystem.py

@@ -152,7 +152,7 @@ def copy_mode(src, dest):
 
 def install(src, dest):
     """Manually install a file to a particular location."""
-    tty.info("Installing %s to %s" % (src, dest))
+    tty.debug("Installing %s to %s" % (src, dest))
     shutil.copy(src, dest)
     set_install_permissions(dest)
     copy_mode(src, dest)
@@ -160,7 +160,7 @@ def install(src, dest):
 
 def install_tree(src, dest, **kwargs):
     """Manually install a file to a particular location."""
-    tty.info("Installing %s to %s" % (src, dest))
+    tty.debug("Installing %s to %s" % (src, dest))
     shutil.copytree(src, dest, **kwargs)
 
     for s, d in traverse_tree(src, dest, follow_nonexisting=False):

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

@@ -36,6 +36,14 @@
 _verbose = False
 indent  = "  "
 
+def is_verbose():
+    return _verbose
+
+
+def is_debug():
+    return _debug
+
+
 def set_debug(flag):
     global _debug
     _debug = flag

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

@@ -99,6 +99,10 @@ def __init__(self, message):
 color_re = r'@(?:@|\.|([*_])?([a-zA-Z])?(?:{((?:[^}]|}})*)})?)'
 
 
+# Force color even if stdout is not a tty.
+_force_color = False
+
+
 class match_to_ansi(object):
     def __init__(self, color=True):
         self.color = color
@@ -162,7 +166,7 @@ def cwrite(string, stream=sys.stdout, color=None):
        then it will be set based on stream.isatty().
     """
     if color is None:
-        color = stream.isatty()
+        color = stream.isatty() or _force_color
     stream.write(colorize(string, color=color))
 
 
@@ -189,7 +193,7 @@ def write(self, string, **kwargs):
             if raw:
                 color=True
             else:
-                color = self._stream.isatty()
+                color = self._stream.isatty() or _force_color
         raw_write(colorize(string, color=color))
 
     def writelines(self, sequence, **kwargs):

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

@@ -0,0 +1,178 @@
+##############################################################################
+# Copyright (c) 2013-2015, Lawrence Livermore National Security, LLC.
+# Produced at the Lawrence Livermore National Laboratory.
+#
+# This file is part of Spack.
+# Written by Todd Gamblin, tgamblin@llnl.gov, All rights reserved.
+# LLNL-CODE-647188
+#
+# For details, see https://scalability-llnl.github.io/spack
+# Please also see the LICENSE file for our notice and the LGPL.
+#
+# This program is free software; you can redistribute it and/or modify
+# it under the terms of the GNU General Public License (as published by
+# the Free Software Foundation) version 2.1 dated February 1999.
+#
+# This program is distributed in the hope that it will be useful, but
+# WITHOUT ANY WARRANTY; without even the IMPLIED WARRANTY OF
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the terms and
+# conditions of the GNU General Public License for more details.
+#
+# You should have received a copy of the GNU Lesser General Public License
+# along with this program; if not, write to the Free Software Foundation,
+# Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
+##############################################################################
+"""Utility classes for logging the output of blocks of code.
+"""
+import sys
+import os
+import re
+import select
+import inspect
+import llnl.util.tty as tty
+import llnl.util.tty.color as color
+
+# Use this to strip escape sequences
+_escape = re.compile(r'\x1b[^m]*m|\x1b\[?1034h')
+
+def _strip(line):
+    """Strip color and control characters from a line."""
+    return _escape.sub('', line)
+
+
+class _SkipWithBlock():
+    """Special exception class used to skip a with block."""
+    pass
+
+
+class log_output(object):
+    """Redirects output and error of enclosed block to a file.
+
+    Usage:
+        with log_output(open('logfile.txt', 'w')):
+           # do things ... output will be logged.
+
+    or:
+        with log_output(open('logfile.txt', 'w'), echo=True):
+           # do things ... output will be logged
+           # and also printed to stdout.
+
+    Closes the provided stream when done with the block.
+    If echo is True, also prints the output to stdout.
+    """
+    def __init__(self, stream, echo=False, force_color=False, debug=False):
+        self.stream = stream
+
+        # various output options
+        self.echo = echo
+        self.force_color = force_color
+        self.debug = debug
+
+    def trace(self, frame, event, arg):
+        """Jumps to __exit__ on the child process."""
+        raise _SkipWithBlock()
+
+
+    def __enter__(self):
+        """Redirect output from the with block to a file.
+
+        This forks the with block as a separate process, with stdout
+        and stderr redirected back to the parent via a pipe.  If
+        echo is set, also writes to standard out.
+
+        """
+        # remember these values for later.
+        self._force_color = color._force_color
+        self._debug = tty._debug
+
+        read, write = os.pipe()
+
+        self.pid = os.fork()
+        if self.pid:
+            # Parent: read from child, skip the with block.
+            os.close(write)
+
+            read_file = os.fdopen(read, 'r', 0)
+            with self.stream as log_file:
+                while True:
+                    rlist, w, x = select.select([read_file], [], [])
+                    if not rlist:
+                        break
+
+                    line = read_file.readline()
+                    if not line:
+                        break
+
+                    # Echo to stdout if requested.
+                    if self.echo:
+                        sys.stdout.write(line)
+
+                    # Stripped output to log file.
+                    log_file.write(_strip(line))
+
+            read_file.flush()
+            read_file.close()
+
+            # Set a trace function to skip the with block.
+            sys.settrace(lambda *args, **keys: None)
+            frame = inspect.currentframe(1)
+            frame.f_trace = self.trace
+
+        else:
+            # Child: redirect output, execute the with block.
+            os.close(read)
+
+            # Save old stdout and stderr
+            self._stdout = os.dup(sys.stdout.fileno())
+            self._stderr = os.dup(sys.stderr.fileno())
+
+            # redirect to the pipe.
+            os.dup2(write, sys.stdout.fileno())
+            os.dup2(write, sys.stderr.fileno())
+
+            if self.force_color:
+                color._force_color = True
+
+            if self.debug:
+                tty._debug = True
+
+
+    def __exit__(self, exc_type, exception, traceback):
+        """Exits on child, handles skipping the with block on parent."""
+        # Child should just exit here.
+        if self.pid == 0:
+            # Flush the log to disk.
+            sys.stdout.flush()
+            sys.stderr.flush()
+
+            if exception:
+                # Restore stdout on the child if there's an exception,
+                # and let it be raised normally.
+                #
+                # This assumes that even if the exception is caught,
+                # the child will exit with a nonzero return code.  If
+                # it doesn't, the child process will continue running.
+                #
+                # TODO: think about how this works outside install.
+                # TODO: ideally would propagate exception to parent...
+                os.dup2(self._stdout, sys.stdout.fileno())
+                os.dup2(self._stderr, sys.stderr.fileno())
+
+                return False
+
+            else:
+                # Die quietly if there was no exception.
+                os._exit(0)
+
+        else:
+            # If the child exited badly, parent also should exit.
+            pid, returncode = os.waitpid(self.pid, 0)
+            if returncode != 0:
+                os._exit(1)
+
+        # restore output options.
+        color._force_color = self._force_color
+        tty._debug = self._debug
+
+        # Suppresses exception if it's our own.
+        return exc_type is _SkipWithBlock

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