diff --git a/lib/spack/spack/build_environment.py b/lib/spack/spack/build_environment.py index 6c4674bd26..ad27b3321d 100644 --- a/lib/spack/spack/build_environment.py +++ b/lib/spack/spack/build_environment.py @@ -1,5 +1,5 @@ ############################################################################## -# Copyright (c) 2013-2016, Lawrence Livermore National Security, LLC. +# Copyright (c) 2013-2017, Lawrence Livermore National Security, LLC. # Produced at the Lawrence Livermore National Laboratory. # # This file is part of Spack. @@ -58,6 +58,7 @@ import sys import traceback from six import iteritems +from six import StringIO import llnl.util.tty as tty from llnl.util.tty.color import colorize @@ -69,6 +70,9 @@ from spack.util.environment import * from spack.util.executable import Executable from spack.util.module_cmd import load_module, get_path_from_module +from spack.util.log_parse import * + + # # This can be set by the user to globally disable parallel builds. # @@ -576,8 +580,12 @@ def child_process(child_pipe, input_stream): 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) + msg = "%s: %s" % (exc_type.__name__, str(exc)) + + ce = ChildError(msg, + exc_type.__module__, + exc_type.__name__, + tb_string, build_log, package_context) child_pipe.send(ce) finally: @@ -657,7 +665,7 @@ def make_stack(tb, stack=None): for i, line in enumerate(sourcelines): is_error = start_ctx + i == l mark = ">> " if is_error else " " - marked = " %s%-5d%s" % (mark, start_ctx + i, line.rstrip()) + marked = " %s%-6d%s" % (mark, start_ctx + i, line.rstrip()) if is_error: marked = colorize('@R{%s}' % marked) lines.append(marked) @@ -683,40 +691,67 @@ class ChildError(spack.error.SpackError): 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. + 3. They also contain context, which shows context in the Package + implementation where the error happened. This helps people debug + Python code in their packages. To get it, 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. + The long_message of a ChildError displays one of two things: + + 1. If the original error was a ProcessError, indicating a command + died during the build, we'll show context from the build log. + + 2. If the original error was any other type of error, we'll show + context from the Python code. + + 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): + # List of errors considered "build errors", for which we'll show log + # context instead of Python context. + build_errors = [('spack.util.executable', 'ProcessError')] + + def __init__(self, msg, module, classname, traceback_string, build_log, + context): super(ChildError, self).__init__(msg) + self.module = module + self.name = classname self.traceback = traceback_string self.build_log = build_log - self.package_context = package_context + self.context = context @property def long_message(self): - msg = self._long_message if self._long_message else '' + out = StringIO() + out.write(self._long_message if self._long_message else '') - if self.package_context: - if msg: - msg += "\n\n" - msg += '\n'.join(self.package_context) + if (self.module, self.name) in ChildError.build_errors: + # The error happened in some external executed process. Show + # the build log with errors highlighted. + if self.build_log: + events = parse_log_events(self.build_log) + out.write("\n%d errors in build log:\n" % len(events)) + out.write(make_log_context(events)) - if msg: - msg += "\n\n" + else: + # The error happened in in the Python code, so try to show + # some context from the Package itself. + out.write('%s: %s\n\n' % (self.name, self.message)) + if self.context: + out.write('\n'.join(self.context)) + out.write('\n') + + if out.getvalue(): + out.write('\n') if self.build_log: - msg += "See build log for details:\n" - msg += " %s" % self.build_log + out.write('See build log for details:\n') + out.write(' %s' % self.build_log) - return msg + return out.getvalue() def __reduce__(self): """__reduce__ is used to serialize (pickle) ChildErrors. @@ -726,11 +761,13 @@ def __reduce__(self): """ return _make_child_error, ( self.message, + self.module, + self.name, self.traceback, self.build_log, - self.package_context) + self.context) -def _make_child_error(msg, traceback, build_log, package_context): +def _make_child_error(msg, module, name, traceback, build_log, context): """Used by __reduce__ in ChildError to reconstruct pickled errors.""" - return ChildError(msg, traceback, build_log, package_context) + return ChildError(msg, module, name, traceback, build_log, context) diff --git a/lib/spack/spack/util/log_parse.py b/lib/spack/spack/util/log_parse.py new file mode 100644 index 0000000000..a55dcf59f5 --- /dev/null +++ b/lib/spack/spack/util/log_parse.py @@ -0,0 +1,134 @@ +############################################################################## +# Copyright (c) 2013-2017, Lawrence Livermore National Security, LLC. +# Produced at the Lawrence Livermore National Laboratory. +# +# This file is part of Spack. +# Created by Todd Gamblin, tgamblin@llnl.gov, All rights reserved. +# LLNL-CODE-647188 +# +# For details, see https://github.com/llnl/spack +# Please also see the NOTICE and LICENSE files 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 Lesser General Public License (as +# published by the Free Software Foundation) version 2.1, 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 Lesser 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 +############################################################################## +from __future__ import print_function + +import re +from six import StringIO + +from llnl.util.tty.color import colorize + + +class LogEvent(object): + """Class representing interesting events (e.g., errors) in a build log.""" + def __init__(self, text, line_no, + pre_context='', post_context='', repeat_count=0): + self.text = text + self.line_no = line_no + self.pre_context = pre_context + self.post_context = post_context + self.repeat_count = repeat_count + + @property + def start(self): + """First line in the log with text for the event or its context.""" + return self.line_no - len(self.pre_context) + + @property + def end(self): + """Last line in the log with text for event or its context.""" + return self.line_no + len(self.post_context) + 1 + + def __getitem__(self, line_no): + """Index event text and context by actual line number in file.""" + if line_no == self.line_no: + return self.text + elif line_no < self.line_no: + return self.pre_context[line_no - self.line_no] + elif line_no > self.line_no: + return self.post_context[line_no - self.line_no - 1] + + def __str__(self): + """Returns event lines and context.""" + out = StringIO() + for i in range(self.start, self.end): + if i == self.line_no: + out.write(' >> %-6d%s' % (i, self[i])) + else: + out.write(' %-6d%s' % (i, self[i])) + return out.getvalue() + + +def parse_log_events(logfile, context=6): + """Extract interesting events from a log file as a list of LogEvent. + + Args: + logfile (str): name of the build log to parse + context (int): lines of context to extract around each log event + + Currently looks for lines that contain the string 'error:', ignoring case. + + TODO: Extract warnings and other events from the build log. + """ + with open(logfile, 'r') as f: + lines = [line for line in f] + + log_events = [] + for i, line in enumerate(lines): + if re.search('error:', line, re.IGNORECASE): + event = LogEvent( + line.strip(), + i + 1, + [l.rstrip() for l in lines[i - context:i]], + [l.rstrip() for l in lines[i + 1:i + context + 1]]) + log_events.append(event) + return log_events + + +def make_log_context(log_events): + """Get error context from a log file. + + Args: + log_events (list of LogEvent): list of events created by, e.g., + ``parse_log_events`` + + Returns: + str: context from the build log with errors highlighted + + Parses the log file for lines containing errors, and prints them out + with line numbers and context. Errors are highlighted with '>>' and + with red highlighting (if color is enabled). + """ + error_lines = set(e.line_no for e in log_events) + + out = StringIO() + next_line = 1 + for event in log_events: + start = event.start + + if start > next_line: + out.write(' [ ... ]\n') + + if start < next_line: + start = next_line + + for i in range(start, event.end): + if i in error_lines: + out.write(colorize(' @R{>> %-6d%s}\n' % (i, event[i]))) + else: + out.write(' %-6d%s\n' % (i, event[i])) + + next_line = event.end + + return out.getvalue()