From edfe2297fd0bd376c8026d9309b241300ab65ed1 Mon Sep 17 00:00:00 2001 From: Todd Gamblin Date: Mon, 31 Oct 2016 15:32:19 -0700 Subject: 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(-) (limited to 'lib') 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.""" -- cgit v1.2.3-70-g09d2