Improved package.py error handling. (#2187)

- Detailed debug information is now handed back to the parent process
  from builds, for *any* type of exception.

- previously this only worked for Spack ProcessErrors, but now it works
  for any type of error raised in a child.

- Spack will print an error message and source code context for build
  errors by default.

- It will print a stack trace when using `spack -d`, even when the error
  occurred in the child process.

4 files changed, 219 insertions, 163 deletions

diff --git a/lib/spack/spack/build_environment.py b/lib/spack/spack/build_environment.py
index f626bab1af..81f893f736 100644
--- a/lib/spack/spack/build_environment.py
+++ b/lib/spack/spack/build_environment.py
@@ -51,10 +51,12 @@ There are two parts to the build environment:
 Skimming this module is a nice way to get acquainted with the types of
 calls you can make from within the install() function.
 """
-import multiprocessing
 import os
-import shutil
 import sys
+import multiprocessing
+import traceback
+import inspect
+import shutil
 
 import llnl.util.tty as tty
 import spack
@@ -530,9 +532,29 @@ def fork(pkg, function, dirty=False):
         try:
             setup_package(pkg, dirty=dirty)
             function()
-            child_connection.send([None, None, None])
-        except Exception as e:
-            child_connection.send([type(e), e, None])
+            child_connection.send(None)
+        except:
+            # catch ANYTHING that goes wrong in the child process
+            exc_type, exc, tb = sys.exc_info()
+
+            # Need to unwind the traceback in the child because traceback
+            # objects can't be sent to the parent.
+            tb_string = traceback.format_exc()
+
+            # build up some context from the offending package so we can
+            # show that, too.
+            package_context = get_package_context(tb)
+
+            build_log = None
+            if hasattr(pkg, 'log_path'):
+                build_log = pkg.log_path
+
+            # make a pickleable exception to send to parent.
+            msg = "%s: %s" % (str(exc_type.__name__), str(exc))
+
+            ce = ChildError(msg, tb_string, build_log, package_context)
+            child_connection.send(ce)
+
         finally:
             child_connection.close()
 
@@ -542,11 +564,126 @@ def fork(pkg, function, dirty=False):
         args=(child_connection,)
     )
     p.start()
-    exc_type, exception, traceback = parent_connection.recv()
+    child_exc = parent_connection.recv()
     p.join()
-    if exception is not None:
-        raise exception
+
+    if child_exc is not None:
+        raise child_exc
+
+
+def get_package_context(traceback):
+    """Return some context for an error message when the build fails.
+
+    Args:
+    traceback -- A traceback from some exception 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.
+
+    """
+    def make_stack(tb, stack=None):
+        """Tracebacks come out of the system in caller -> callee order.  Return
+        an array in callee -> caller order so we can traverse it."""
+        if stack is None:
+            stack = []
+        if tb is not None:
+            make_stack(tb.tb_next, stack)
+            stack.append(tb)
+        return stack
+
+    stack = make_stack(traceback)
+
+    for tb in stack:
+        frame = tb.tb_frame
+        if 'self' in frame.f_locals:
+            # Find the first proper subclass of spack.PackageBase.
+            obj = frame.f_locals['self']
+            if isinstance(obj, spack.PackageBase):
+                break
+
+    # we found obj, the Package implementation we care about.
+    # point out the location in the install method where we failed.
+    lines = []
+    lines.append("%s:%d, in %s:" % (
+        inspect.getfile(frame.f_code), frame.f_lineno, frame.f_code.co_name
+    ))
+
+    # Build a message showing context in the install method.
+    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
 
 
 class InstallError(spack.error.SpackError):
-    """Raised when a package fails to install"""
+    """Raised by packages when a package fails to install"""
+
+
+class ChildError(spack.error.SpackError):
+    """Special exception class for wrapping exceptions from child processes
+       in Spack's build environment.
+
+    The main features of a ChildError are:
+
+    1. They're serializable, so when a child build fails, we can send one
+       of these to the parent and let the parent report what happened.
+
+    2. They have a ``traceback`` field containing a traceback generated
+       on the child immediately after failure.  Spack will print this on
+       failure in lieu of trying to run sys.excepthook on the parent
+       process, so users will see the correct stack trace from a child.
+
+    3. They also contain package_context, which shows source code context
+       in the Package implementation where the error happened.  To get
+       this, Spack searches the stack trace for the deepest frame where
+       ``self`` is in scope and is an instance of PackageBase.  This will
+       generally find a useful spot in the ``package.py`` file.
+
+    The long_message of a ChildError displays all this stuff to the user,
+    and SpackError handles displaying the special traceback if we're in
+    debug mode with spack -d.
+
+    """
+    def __init__(self, msg, traceback_string, build_log, package_context):
+        super(ChildError, self).__init__(msg)
+        self.traceback = traceback_string
+        self.build_log = build_log
+        self.package_context = package_context
+
+    @property
+    def long_message(self):
+        msg = self._long_message if self._long_message else ''
+
+        if self.package_context:
+            if msg:
+                msg += "\n\n"
+            msg += '\n'.join(self.package_context)
+
+        if msg:
+            msg += "\n\n"
+
+        if self.build_log:
+            msg += "See build log for details:\n"
+            msg += "  %s" % self.build_log
+
+        return msg
+
+    def __reduce__(self):
+        """__reduce__ is used to serialize (pickle) ChildErrors.
+
+        Return a function to reconstruct a ChildError, along with the
+        salient properties we'll need.
+        """
+        return _make_child_error, (
+            self.message,
+            self.traceback,
+            self.build_log,
+            self.package_context)
+
+
+def _make_child_error(msg, traceback, build_log, package_context):
+    """Used by __reduce__ in ChildError to reconstruct pickled errors."""
+    return ChildError(msg, traceback, build_log, package_context)
diff --git a/lib/spack/spack/error.py b/lib/spack/spack/error.py
index 5e5c1b1c7e..b6261a05f4 100644
--- a/lib/spack/spack/error.py
+++ b/lib/spack/spack/error.py
@@ -39,19 +39,31 @@ class SpackError(Exception):
         self.message = message
         self._long_message = long_message
 
+        # for exceptions raised from child build processes, we save the
+        # traceback as a string and print it in the parent.
+        self.traceback = None
+
     @property
     def long_message(self):
         return self._long_message
 
     def die(self):
+        # basic debug message
+        tty.error(self.message)
+        if self.long_message:
+            print(self.long_message)
+
+        # stack trace, etc. in debug mode.
         if spack.debug:
-            sys.excepthook(*sys.exc_info())
-            os._exit(1)
-        else:
-            tty.error(self.message)
-            if self.long_message:
-                print(self.long_message)
-            os._exit(1)
+            if self.traceback:
+                # exception came from a build child, already got
+                # traceback in child, so print it.
+                sys.stderr.write(self.traceback)
+            else:
+                # run parent exception hook.
+                sys.excepthook(*sys.exc_info())
+
+        os._exit(1)
 
     def __str__(self):
         msg = self.message
diff --git a/lib/spack/spack/package.py b/lib/spack/spack/package.py
index 491e21bf95..8ce8da1ff2 100644
--- a/lib/spack/spack/package.py
+++ b/lib/spack/spack/package.py
@@ -65,7 +65,6 @@ from spack import directory_layout
 from spack.stage import Stage, ResourceStage, StageComposite
 from spack.util.crypto import bit_length
 from spack.util.environment import dump_environment
-from spack.util.executable import ProcessError
 from spack.version import *
 
 """Allowed URL schemes for spack packages."""
@@ -96,6 +95,8 @@ class InstallPhase(object):
         # install phase, thus return a properly set wrapper
         phase = getattr(instance, self.name)
 
+        print phase
+
         @functools.wraps(phase)
         def phase_wrapper(spec, prefix):
             # Check instance attributes at the beginning of a phase
@@ -1213,60 +1214,57 @@ class PackageBase(object):
 
             self.stage.keep = keep_stage
 
-            try:
-                with contextlib.nested(self.stage, self._prefix_write_lock()):
-                    # Run the pre-install hook in the child process after
-                    # the directory is created.
-                    spack.hooks.pre_install(self)
-                    if fake:
-                        self.do_fake_install()
-                    else:
-                        # Do the real install in the source directory.
-                        self.stage.chdir_to_source()
-                        # Save the build environment in a file before building.
-                        env_path = join_path(os.getcwd(), 'spack-build.env')
-                        # Redirect I/O to a build log (and optionally to
-                        # the terminal)
-                        log_path = join_path(os.getcwd(), 'spack-build.out')
-                        # FIXME : refactor this assignment
-                        self.log_path = log_path
-                        self.env_path = env_path
-                        dump_environment(env_path)
-                        # Spawn a daemon that reads from a pipe and redirects
-                        # everything to log_path
-                        redirection_context = log_output(
-                            log_path, verbose,
-                            sys.stdout.isatty(),
-                            True
-                        )
-                        with redirection_context as log_redirection:
-                            for phase_name, phase in zip(self.phases, self._InstallPhase_phases):  # NOQA: ignore=E501
-                                tty.msg(
-                                    'Executing phase : \'{0}\''.format(phase_name)  # NOQA: ignore=E501
-                                )
-                                # Redirect stdout and stderr to daemon pipe
-                                with log_redirection:
-                                    getattr(self, phase)(
-                                        self.spec, self.prefix)
-                        self.log()
-                    # Run post install hooks before build stage is removed.
-                    spack.hooks.post_install(self)
-
-                # Stop timer.
-                self._total_time = time.time() - start_time
-                build_time = self._total_time - self._fetch_time
-
-                tty.msg("Successfully installed %s" % self.name,
-                        "Fetch: %s.  Build: %s.  Total: %s." %
-                        (_hms(self._fetch_time), _hms(build_time),
-                         _hms(self._total_time)))
-                print_pkg(self.prefix)
-
-            except ProcessError as e:
-                # Annotate ProcessErrors with the location of
-                # the build log
-                e.build_log = log_path
-                raise e
+            with contextlib.nested(self.stage, self._prefix_write_lock()):
+                # Run the pre-install hook in the child process after
+                # the directory is created.
+                spack.hooks.pre_install(self)
+                if fake:
+                    self.do_fake_install()
+                else:
+                    # Do the real install in the source directory.
+                    self.stage.chdir_to_source()
+
+                    # Save the build environment in a file before building.
+                    env_path = join_path(os.getcwd(), 'spack-build.env')
+
+                    # Redirect I/O to a build log (and optionally to
+                    # the terminal)
+                    log_path = join_path(os.getcwd(), 'spack-build.out')
+
+                    # FIXME : refactor this assignment
+                    self.log_path = log_path
+                    self.env_path = env_path
+                    dump_environment(env_path)
+
+                    # Spawn a daemon that reads from a pipe and redirects
+                    # everything to log_path
+                    redirection_context = log_output(
+                        log_path, verbose,
+                        sys.stdout.isatty(),
+                        True
+                    )
+                    with redirection_context as log_redirection:
+                        for phase_name, phase in zip(self.phases, self._InstallPhase_phases):  # NOQA: ignore=E501
+                            tty.msg(
+                                'Executing phase : \'{0}\''.format(phase_name)  # NOQA: ignore=E501
+                            )
+                            # Redirect stdout and stderr to daemon pipe
+                            with log_redirection:
+                                getattr(self, phase)(
+                                    self.spec, self.prefix)
+                    self.log()
+                # Run post install hooks before build stage is removed.
+                spack.hooks.post_install(self)
+
+            # Stop timer.
+            self._total_time = time.time() - start_time
+            build_time = self._total_time - self._fetch_time
+
+            tty.msg("Successfully installed %s" % self.name,
+                    "Fetch: %s.  Build: %s.  Total: %s." %
+                    (_hms(self._fetch_time), _hms(build_time),
+                     _hms(self._total_time)))
+            print_pkg(self.prefix)
 
         try:
             # Create the install prefix and fork the build process.
diff --git a/lib/spack/spack/util/executable.py b/lib/spack/spack/util/executable.py
index fbcb172f0c..63bbbb7c92 100644
--- a/lib/spack/spack/util/executable.py
+++ b/lib/spack/spack/util/executable.py
@@ -26,7 +26,6 @@
 import os
 import re
 import subprocess
-import inspect
 
 import llnl.util.tty as tty
 import spack
@@ -237,94 +236,4 @@ def which(name, **kwargs):
 
 
 class ProcessError(spack.error.SpackError):
-
-    def __init__(self, msg, long_message=None):
-        # These are used for detailed debugging information for
-        # package builds.  They're built up gradually as the exception
-        # propagates.
-        self.package_context = _get_package_context()
-        self.build_log = None
-
-        super(ProcessError, self).__init__(msg, long_message)
-
-    @property
-    def long_message(self):
-
-        msg = self._long_message if self._long_message else ''
-
-        if self.package_context:
-            if msg:
-                msg += "\n\n"
-            msg += '\n'.join(self.package_context)
-
-        if msg:
-            msg += "\n\n"
-
-        if self.build_log:
-            msg += "See build log for details:\n"
-            msg += "  %s" % self.build_log
-
-        return msg
-
-    def __reduce__(self):
-        # We need this constructor because we are trying to move a ProcessError
-        # across processes. This means that we have to preserve the original
-        # package context and build log
-        return _make_process_error, (
-            self.message,
-            self._long_message,
-            self.package_context,
-            self.build_log
-        )
-
-
-def _make_process_error(msg, long_message, pkg_context, build_log):
-    a = ProcessError(msg, long_message)
-    a.package_context = pkg_context
-    a.build_log = build_log
-    return a
-
-
-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 'self' not 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.PackageBase and isinstance(obj, spack.PackageBase):  # NOQA: ignore=E501
-            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
+    """ProcessErrors are raised when Executables exit with an error code."""