surface build error content through test event system

Summary:
print build errors nicely in test output

This test infrastructure change adds a new Python exception
for test subject builds that fail.  The output of the build
command is captured and propagated to both the textual test
output display code and to the test event system.

The ResultsFormatter objects have been modified to do something
more useful with this information.  The xUnit formatter
now replaces the non-informative Python build error stacktrace
with the build error content.  The curses ResultsFormatter
prints a 'B' for build errors rather than 'E'.

The xUnit output, in particular, makes it much easier for
developers to track down test subject build errors that cause
test failures when reports come in from CI.

Reviewers: granata.enrico

Subscribers: llvm-commits

Differential Revision: http://reviews.llvm.org/D20252

llvm-svn: 269525

lldb/packages/Python/lldbsuite/test/lldbtest.py

@@ -419,7 +419,14 @@ def system(commands, **kwargs):
             cmd = kwargs.get("args")
             if cmd is None:
                 cmd = shellCommand
-            raise CalledProcessError(retcode, cmd)
+            cpe = CalledProcessError(retcode, cmd)
+            # Ensure caller can access the stdout/stderr.
+            cpe.lldb_extensions = {
+                "stdout_content": this_output,
+                "stderr_content": this_error,
+                "command": shellCommand
+            }
+            raise cpe
         output = output + this_output
         error = error + this_error
     return (output, error)

lldb/packages/Python/lldbsuite/test/plugins/builder_base.py

@@ -12,10 +12,16 @@ Same idea holds for LLDB_ARCH environment variable, which maps to the ARCH make
 variable.
 """
 
-import os, sys
+# System imports
+import os
 import platform
+import subprocess
+import sys
+
+# Our imports
 import lldbsuite.test.lldbtest as lldbtest
 import lldbsuite.test.lldbutil as lldbutil
+from lldbsuite.test_event import build_exception
 
 def getArchitecture():
     """Returns the architecture in effect the test suite is running with."""
@@ -93,6 +99,16 @@ def getCmdLine(d):
     return cmdline
 
 
+def runBuildCommands(commands, sender):
+    try:
+        lldbtest.system(commands, sender=sender)
+    except subprocess.CalledProcessError as called_process_error:
+        # Convert to a build-specific error.
+        # We don't do that in lldbtest.system() since that
+        # is more general purpose.
+        raise build_exception.BuildError(called_process_error)
+
+
 def buildDefault(sender=None, architecture=None, compiler=None, dictionary=None, clean=True):
     """Build the binaries the default way."""
     commands = []
@@ -100,7 +116,7 @@ def buildDefault(sender=None, architecture=None, compiler=None, dictionary=None,
         commands.append([getMake(), "clean", getCmdLine(dictionary)])
     commands.append([getMake(), getArchSpec(architecture), getCCSpec(compiler), getCmdLine(dictionary)])
 
-    lldbtest.system(commands, sender=sender)
+    runBuildCommands(commands, sender=sender)
 
     # True signifies that we can handle building default.
     return True
@@ -112,7 +128,7 @@ def buildDwarf(sender=None, architecture=None, compiler=None, dictionary=None, c
         commands.append([getMake(), "clean", getCmdLine(dictionary)])
     commands.append([getMake(), "MAKE_DSYM=NO", getArchSpec(architecture), getCCSpec(compiler), getCmdLine(dictionary)])
 
-    lldbtest.system(commands, sender=sender)
+    runBuildCommands(commands, sender=sender)
     # True signifies that we can handle building dwarf.
     return True
 
@@ -123,7 +139,7 @@ def buildDwo(sender=None, architecture=None, compiler=None, dictionary=None, cle
         commands.append([getMake(), "clean", getCmdLine(dictionary)])
     commands.append([getMake(), "MAKE_DSYM=NO", "MAKE_DWO=YES", getArchSpec(architecture), getCCSpec(compiler), getCmdLine(dictionary)])
 
-    lldbtest.system(commands, sender=sender)
+    runBuildCommands(commands, sender=sender)
     # True signifies that we can handle building dwo.
     return True
 
@@ -135,6 +151,6 @@ def cleanup(sender=None, dictionary=None):
     if os.path.isfile("Makefile"):
         commands.append([getMake(), "clean", getCmdLine(dictionary)])
 
-    lldbtest.system(commands, sender=sender)
+    runBuildCommands(commands, sender=sender)
     # True signifies that we can handle cleanup.
     return True

lldb/packages/Python/lldbsuite/test/plugins/builder_darwin.py

@@ -5,8 +5,6 @@ import lldbsuite.test.lldbtest as lldbtest
 
 from builder_base import *
 
-#print("Hello, darwin plugin!")
-
 def buildDsym(sender=None, architecture=None, compiler=None, dictionary=None, clean=True):
     """Build the binaries with dsym debug info."""
     commands = []
@@ -15,7 +13,7 @@ def buildDsym(sender=None, architecture=None, compiler=None, dictionary=None, cl
         commands.append(["make", "clean", getCmdLine(dictionary)])
     commands.append(["make", "MAKE_DSYM=YES", getArchSpec(architecture), getCCSpec(compiler), getCmdLine(dictionary)])
 
-    lldbtest.system(commands, sender=sender)
+    runBuildCommands(commands, sender=sender)
 
     # True signifies that we can handle building dsym.
     return True

lldb/packages/Python/lldbsuite/test/test_result.py

@@ -13,6 +13,7 @@ from __future__ import print_function
 
 # System modules
 import inspect
+import os
 
 # Third-party modules
 import unittest2
@@ -20,7 +21,7 @@ import unittest2
 # LLDB Modules
 from . import configuration
 from lldbsuite.test_event.event_builder import EventBuilder
-
+from lldbsuite.test_event import build_exception
 
 class LLDBTestResult(unittest2.TextTestResult):
     """
@@ -139,17 +140,48 @@ class LLDBTestResult(unittest2.TextTestResult):
             self.results_formatter.handle_event(
                 EventBuilder.event_for_success(test))
 
+    def _isBuildError(self, err_tuple):
+        exception = err_tuple[1]
+        return isinstance(exception, build_exception.BuildError)
+
+    def _getTestPath(self, test):
+        if test is None:
+            return ""
+        elif hasattr(test, "test_filename"):
+            return test.test_filename
+        else:
+            return inspect.getsourcefile(test.__class__)
+
+
+    def _saveBuildErrorTuple(self, test, err):
+        # Adjust the error description so it prints the build command and build error
+        # rather than an uninformative Python backtrace.
+        build_error = err[1]
+        error_description = "{}\nTest Directory:\n{}".format(
+            str(build_error),
+            os.path.dirname(self._getTestPath(test)))
+        self.errors.append((test, error_description))
+        self._mirrorOutput = True
+
     def addError(self, test, err):
         configuration.sdir_has_content = True
-        super(LLDBTestResult, self).addError(test, err)
+        if self._isBuildError(err):
+            self._saveBuildErrorTuple(test, err)
+        else:
+            super(LLDBTestResult, self).addError(test, err)
+
         method = getattr(test, "markError", None)
         if method:
             method()
         if configuration.parsable:
             self.stream.write("FAIL: LLDB (%s) :: %s\n" % (self._config_string(test), str(test)))
         if self.results_formatter:
-            self.results_formatter.handle_event(
+            # Handle build errors as a separate event type
-                EventBuilder.event_for_error(test, err))
+            if self._isBuildError(err):
+                error_event = EventBuilder.event_for_build_error(test, err)
+            else:
+                error_event = EventBuilder.event_for_error(test, err)
+            self.results_formatter.handle_event(error_event)
 
     def addCleanupError(self, test, err):
         configuration.sdir_has_content = True

lldb/packages/Python/lldbsuite/test_event/build_exception.py

@@ -0,0 +1,14 @@
+class BuildError(Exception):
+    def __init__(self, called_process_error):
+        super(BuildError, self).__init__("Error when building test subject")
+        self.command = called_process_error.lldb_extensions.get("command", "<command unavailable>")
+        self.build_error = called_process_error.lldb_extensions.get("stderr_content", "<error output unavailable>")
+
+    def __str__(self):
+        return self.format_build_error(self.command, self.build_error)
+
+    @staticmethod
+    def format_build_error(command, command_output):
+        return "Error when building test subject.\n\nBuild Command:\n{}\n\nBuild Command Output:\n{}".format(
+            command,
+            command_output)

lldb/packages/Python/lldbsuite/test_event/event_builder.py

@@ -18,7 +18,7 @@ import traceback
 # Third-party modules
 
 # LLDB modules
-
+from . import build_exception
 
 class EventBuilder(object):
     """Helper class to build test result event dictionaries."""
@@ -49,7 +49,11 @@ class EventBuilder(object):
     """Test methods or jobs with a status matching any of these
     status values will cause a testrun failure, unless
     the test methods rerun and do not trigger an issue when rerun."""
-    TESTRUN_ERROR_STATUS_VALUES = {STATUS_ERROR, STATUS_EXCEPTIONAL_EXIT, STATUS_FAILURE, STATUS_TIMEOUT}
+    TESTRUN_ERROR_STATUS_VALUES = {
+        STATUS_ERROR,
+        STATUS_EXCEPTIONAL_EXIT,
+        STATUS_FAILURE,
+        STATUS_TIMEOUT}
 
     @staticmethod
     def _get_test_name_info(test):
@@ -300,8 +304,31 @@ class EventBuilder(object):
 
         @return the event dictionary
         """
-        return EventBuilder._event_dictionary_issue(
+        event = EventBuilder._event_dictionary_issue(
             test, EventBuilder.STATUS_ERROR, error_tuple)
+        event["issue_phase"] = "test"
+        return event
+
+    @staticmethod
+    def event_for_build_error(test, error_tuple):
+        """Returns an event dictionary for a test that hit a test execution error
+        during the test cleanup phase.
+
+        @param test a unittest.TestCase instance.
+
+        @param error_tuple the error tuple as reported by the test runner.
+        This is of the form (type<error>, error).
+
+        @return the event dictionary
+        """
+        event = EventBuilder._event_dictionary_issue(
+            test, EventBuilder.STATUS_ERROR, error_tuple)
+        event["issue_phase"] = "build"
+
+        build_error = error_tuple[1]
+        event["build_command"] = build_error.command
+        event["build_error"] = build_error.build_error
+        return event
 
     @staticmethod
     def event_for_cleanup_error(test, error_tuple):

lldb/packages/Python/lldbsuite/test_event/formatter/curses.py

@@ -59,7 +59,7 @@ class Curses(results_formatter.ResultsFormatter):
         # if tee_results_formatter:
         #     self.formatters.append(tee_results_formatter)
 
-    def status_to_short_str(self, status):
+    def status_to_short_str(self, status, test_event):
         if status == EventBuilder.STATUS_SUCCESS:
             return '.'
         elif status == EventBuilder.STATUS_FAILURE:
@@ -71,7 +71,11 @@ class Curses(results_formatter.ResultsFormatter):
         elif status == EventBuilder.STATUS_SKIP:
             return 'S'
         elif status == EventBuilder.STATUS_ERROR:
-            return 'E'
+            if test_event.get("issue_phase", None) == "build":
+                # Build failure
+                return 'B'
+            else:
+                return 'E'
         elif status == EventBuilder.STATUS_TIMEOUT:
             return 'T'
         elif status == EventBuilder.STATUS_EXPECTED_TIMEOUT:
@@ -123,7 +127,7 @@ class Curses(results_formatter.ResultsFormatter):
             if status in self.hide_status_list:
                 continue
             name = test_result['test_class'] + '.' + test_result['test_name']
-            self.results_panel.append_line('%s (%6.2f sec) %s' % (self.status_to_short_str(status), test_result['elapsed_time'], name))
+            self.results_panel.append_line('%s (%6.2f sec) %s' % (self.status_to_short_str(status, test_result), test_result['elapsed_time'], name))
         if update:
             self.main_window.refresh()
 
@@ -162,7 +166,7 @@ class Curses(results_formatter.ResultsFormatter):
                         name = test_event['test_class'] + '.' + test_event['test_name']
                         elapsed_time = test_event['event_time'] - self.job_tests[worker_index]['event_time']
                         if not status in self.hide_status_list:
-                            self.results_panel.append_line('%s (%6.2f sec) %s' % (self.status_to_short_str(status), elapsed_time, name))
+                            self.results_panel.append_line('%s (%6.2f sec) %s' % (self.status_to_short_str(status, test_event), elapsed_time, name))
                         self.main_window.refresh()
                         # Append the result pairs
                         test_event['elapsed_time'] = elapsed_time

lldb/packages/Python/lldbsuite/test_event/formatter/xunit.py

@@ -21,6 +21,7 @@ import six
 
 # Local modules
 from ..event_builder import EventBuilder
+from ..build_exception import BuildError
 from .results_formatter import ResultsFormatter
 
 
@@ -246,7 +247,28 @@ class XunitFormatter(ResultsFormatter):
         with self.lock:
             self.elements["failures"].append(result)
 
-    def _handle_error(self, test_event):
+    def _handle_error_build(self, test_event):
+        """Handles a test error.
+        @param test_event the test event to handle.
+        """
+        message = self._replace_invalid_xml(test_event["issue_message"])
+        build_issue_description = self._replace_invalid_xml(
+            BuildError.format_build_error(
+                test_event.get("build_command", "<None>"),
+                test_event.get("build_error", "<None>")))
+
+        result = self._common_add_testcase_entry(
+            test_event,
+            inner_content=(
+                '<error type={} message={}><![CDATA[{}]]></error>'.format(
+                    XunitFormatter._quote_attribute(test_event["issue_class"]),
+                    XunitFormatter._quote_attribute(message),
+                    build_issue_description)
+            ))
+        with self.lock:
+            self.elements["errors"].append(result)
+
+    def _handle_error_standard(self, test_event):
         """Handles a test error.
         @param test_event the test event to handle.
         """
@@ -265,6 +287,12 @@ class XunitFormatter(ResultsFormatter):
         with self.lock:
             self.elements["errors"].append(result)
 
+    def _handle_error(self, test_event):
+        if test_event.get("issue_phase", None) == "build":
+            self._handle_error_build(test_event)
+        else:
+            self._handle_error_standard(test_event)
+
     def _handle_exceptional_exit(self, test_event):
         """Handles an exceptional exit.
         @param test_event the test method or job result event to handle.