From edfe2297fd0bd376c8026d9309b241300ab65ed1 Mon Sep 17 00:00:00 2001
From: Todd Gamblin <tgamblin@llnl.gov>
Date: Mon, 31 Oct 2016 15:32:19 -0700
Subject: [PATCH] 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.
---
lib/spack/spack/build_environment.py | 155 +++++++++++++++++++++++++--
lib/spack/spack/error.py | 26 +++--
lib/spack/spack/package.py | 108 +++++++++----------
lib/spack/spack/util/executable.py | 93 +---------------
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 @@
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 child_execution(child_connection):
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 child_execution(child_connection):
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 @@ def __init__(self, message, long_message=None):
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.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 @@ def __get__(self, instance, owner):
# 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 @@ def build_process():
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."""
--
GitLab