Display build output on ProcessError, instead of Python context.

- If a failure comes from an external command and NOT the Python code,
  display errors highlighted with some context.

- Add some rudimentary support for parsing errors out of the build log
  (not very sophisticated yet).

- Build errors in Python code will still display with Python context.

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))
+            msg = "%s: %s" % (exc_type.__name__, str(exc))
-            ce = ChildError(msg, tb_string, build_log, package_context)
+
+            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
+    3. They also contain context, which shows context in the Package
-       in the Package implementation where the error happened.  To get
+       implementation where the error happened.  This helps people debug
-       this, Spack searches the stack trace for the deepest frame where
+       Python code in their packages.  To get it, Spack searches the
-       ``self`` is in scope and is an instance of PackageBase.  This will
+       stack trace for the deepest frame where ``self`` is in scope and
-       generally find a useful spot in the ``package.py`` file.
+       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,
+    The long_message of a ChildError displays one of two things:
-    and SpackError handles displaying the special traceback if we're in
+
-    debug mode with spack -d.
+      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 (self.module, self.name) in ChildError.build_errors:
-            if msg:
+            # The error happened in some external executed process. Show
-                msg += "\n\n"
+            # the build log with errors highlighted.
-            msg += '\n'.join(self.package_context)
+            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:
+        else:
-            msg += "\n\n"
+            # 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"
+            out.write('See build log for details:\n')
-            msg += "  %s" % self.build_log
+            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)

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()