surface build error content through test event system

[tfiala]

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.

[tfiala]

This was my first time using arcanist to submit a code review with a git-svn setup. I'm trying to use that code workflow - expect possible workflow n00b issues throughout this review.

[tfiala]

As an example of output, here's what the textual output for a (force, contrived) build error looks like now:

Configuration: arch=x86_64 compiler=clang
----------------------------------------------------------------------
Collected 2 tests

======================================================================
ERROR: test_typedef_dsym (Testtypedef.TypedefTestCase)
   Test 'image lookup -t a' and check for correct display at different scopes.
----------------------------------------------------------------------
Error when building test subject.

Test Directory:
/Volumes/Data/src/lldb-llvm.org/lldb/packages/Python/lldbsuite/test/lang/c/typedef

Build Command:
make MAKE_DSYM=YES ARCH=x86_64 CC="clang"

Build Output:
main.c:10:10: fatal error: 'idontexist.h' file not found
#include <idontexist.h>
         ^
1 error generated.
make: *** [main.o] Error 1

======================================================================
ERROR: test_typedef_dwarf (Testtypedef.TypedefTestCase)
   Test 'image lookup -t a' and check for correct display at different scopes.
----------------------------------------------------------------------
Error when building test subject.

Test Directory:
/Volumes/Data/src/lldb-llvm.org/lldb/packages/Python/lldbsuite/test/lang/c/typedef

Build Command:
make MAKE_DSYM=NO ARCH=x86_64 CC="clang"

Build Output:
main.c:10:10: fatal error: 'idontexist.h' file not found
#include <idontexist.h>
         ^
1 error generated.
make: *** [main.o] Error 1

----------------------------------------------------------------------
Ran 2 tests in 0.754s

RESULT: FAILED (0 passes, 0 failures, 2 errors, 0 skipped, 0 expected failures, 0 unexpected successes)
Session logs for test failures/errors/unexpected successes can be found in directory '2016-05-13-11_42_40'

That's much more informative as to what went wrong. Previously we'd just get a Python backtrace that said one of the build routines failed, with no output as to what build failure occurred.

[granata.enrico]

packages/Python/lldbsuite/test/lldbtest.py

422 ↗

(On Diff #57229)

I don't have a strong opinion either way, this is just me offering an alternative

Does it make sense to have custom members on the CalledProcessError object? It is not a big deal, unless some of our member names conflict with ones that Python may want to use - but in general, if we think we may want to expand the set, is there any advantage to custom member variables vs. attaching a custom dictionary:

cpe.LLDB_test_build_error_data = {'output' : ... }

Up to you really. I have seen and used both styles at different times.

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

109 ↗

(On Diff #57229)

Could we make BuildError's init take a CalledProcessError directly, and extract data out of it as it sees fit?

packages/Python/lldbsuite/test/test_result.py

145 ↗

(On Diff #57229)

I would use isinstance() here

160 ↗

(On Diff #57229)

Could this be done by adding a str() or repr() method on BuildError instead?

packages/Python/lldbsuite/test_event/build_exception.py

6 ↗

(On Diff #57229)

Newline at the end :-)

[tfiala]

Great feedback. I'll address them in a follow-up patch.

packages/Python/lldbsuite/test/lldbtest.py

422 ↗

(On Diff #57229)

Sure, dictionary sounds fine.

Effective Python (IIRC) recommended against making member accessors on the basis of there is no real protection against direct access to the members. But the dictionary seems reasonable.

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

109 ↗

(On Diff #57229)

Yes, I like that idea.

packages/Python/lldbsuite/test/test_result.py

145 ↗

(On Diff #57229)

Okay, I'll have a look at that. I know None behaves properly with type(), not sure if it does with isinstance().

160 ↗

(On Diff #57229)

Sure. Removes duplication in another location (xUnit formatter). Good call.

packages/Python/lldbsuite/test_event/build_exception.py

6 ↗

(On Diff #57229)

Ah yes. I unintentionally forgot to add this initially (git add was forgotten), and I blew it away when preparing to put this up for review. This one I rewrote too fast.

[tfiala]

• Merge remote-tracking branch 'origin/master' into surface-build-error
• changes per review from Enrico

[tfiala]

I think I hit all the comments you indicated with the new patch set.

packages/Python/lldbsuite/test/test_result.py

145 ↗

(On Diff #57229)

Yep none works fine here.

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

for shellCommand in commandList:
             print("stderr:", this_error, file=sbuf)
             print("retcode:", retcode, file=sbuf)
             print(file=sbuf)
 
         if retcode:
             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)
 
 def getsource_if_available(obj):
     """
     Return the text of the source code for an object if available.  Otherwise,
     a print representation is returned.

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

 """
 If the build* function is passed the compiler argument, for example, 'llvm-gcc',
 it is passed as a make variable to the make command.  Otherwise, we check the
 LLDB_CC environment variable; if it is defined, it is passed as a make variable
 to the make command.
 
 If neither the compiler keyword argument nor the LLDB_CC environment variable is
 specified, no CC make variable is passed to the make command.  The Makefile gets
 to define the default CC being used.
 
 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."""
     return os.environ["ARCH"] if "ARCH" in os.environ else ""
 
 def getCompiler():
     """Returns the compiler in effect the test suite is running with."""
     compiler = os.environ.get("CC", "clang")
def setOrAppendVariable(k, v):
         if k in append_vars and k in os.environ:
             v = os.environ[k] + " " + v
         return pattern % (k, v)
     cmdline = " ".join([setOrAppendVariable(k, v) for k, v in list(d.items())])
 
     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 = []
     if clean:
         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
 
 def buildDwarf(sender=None, architecture=None, compiler=None, dictionary=None, clean=True):
     """Build the binaries with dwarf debug info."""
     commands = []
     if clean:
         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
 
 def buildDwo(sender=None, architecture=None, compiler=None, dictionary=None, clean=True):
     """Build the binaries with dwarf debug info."""
     commands = []
     if clean:
         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
 
 def cleanup(sender=None, dictionary=None):
     """Perform a platform-specific cleanup after the test."""
     #import traceback
     #traceback.print_stack()
     commands = []
     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/trunk/packages/Python/lldbsuite/test/plugins/builder_darwin.py

 
 from __future__ import print_function
 import os
 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 = []
 
     if clean:
         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/trunk/packages/Python/lldbsuite/test/test_result.py

 """
                      The LLVM Compiler Infrastructure
 
 This file is distributed under the University of Illinois Open Source
 License. See LICENSE.TXT for details.
 
 Provides the LLDBTestResult class, which holds information about progress
 and results of a single test run.
 """
 
 from __future__ import absolute_import
 from __future__ import print_function
 
 # System modules
 import inspect
+import os
 
 # Third-party modules
 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):
     """
     Enforce a singleton pattern to allow introspection of test progress.
 
     Overwrite addError(), addFailure(), and addExpectedFailure() methods
     to enable each test instance to track its failure/error status.  It
     is used in the LLDB test framework to emit detailed trace messages
class LLDBTestResult(unittest2.TextTestResult):
     def addSuccess(self, test):
         super(LLDBTestResult, self).addSuccess(test)
         if configuration.parsable:
             self.stream.write("PASS: LLDB (%s) :: %s\n" % (self._config_string(test), str(test)))
         if self.results_formatter:
             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
+        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(
-                EventBuilder.event_for_error(test, err))
+            # Handle build errors as a separate event type
+            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
         super(LLDBTestResult, self).addCleanupError(test, err)
         method = getattr(test, "markCleanupError", None)
         if method:
             method()
         if configuration.parsable:

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

+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/trunk/packages/Python/lldbsuite/test_event/event_builder.py

 # System modules
 import inspect
 import time
 import traceback
 
 # Third-party modules
 
 # LLDB modules
-
+from . import build_exception
 
 class EventBuilder(object):
     """Helper class to build test result event dictionaries."""
 
     BASE_DICTIONARY = None
 
     # Test Event Types
     TYPE_JOB_RESULT = "job_result"
class EventBuilder(object):
     STATUS_UNEXPECTED_SUCCESS = "unexpected_success"
     STATUS_SKIP = "skip"
     STATUS_ERROR = "error"
     STATUS_TIMEOUT = "timeout"
 
     """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):
         """Returns (test-class-name, test-method-name) from a test case instance.
 
         @param test a unittest.TestCase instance.
 
         @return tuple containing (test class name, test method name)
def event_for_error(test, error_tuple):
 
         @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
         """
-        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):
         """Returns an event dictionary for a test that hit a test execution error
         during the test cleanup phase.
 
         @param test a unittest.TestCase instance.
 

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

def __init__(self, out_file, options, file_is_stream):
             raise
 
         self.line_dict = dict()
         # self.events_file = open("/tmp/events.txt", "w")
         # self.formatters = list()
         # 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:
             return 'F'
         elif status == EventBuilder.STATUS_UNEXPECTED_SUCCESS:
             return '?'
         elif status == EventBuilder.STATUS_EXPECTED_FAILURE:
             return 'X'
         elif status == EventBuilder.STATUS_SKIP:
             return 'S'
         elif status == EventBuilder.STATUS_ERROR:
+            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:
             return 't'
         else:
             return status
 
     def show_info_panel(self):
def update_results(self, update=True):
            what the user desires to see.'''
         self.results_panel.clear(update=False)
         for result in self.results:
             test_result = result[1]
             status = test_result['status']
             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()
 
     def handle_event(self, test_event):
         with self.lock:
             super(Curses, self).handle_event(test_event)
             # for formatter in self.formatters:
             #     formatter.process_event(test_event)
def handle_event(self, test_event):
                         if 'pid' in test_event:
                             line = 'pid: %5d ' % (test_event['pid'])
                         else:
                             line = ''
                         self.job_panel.set_line(worker_index, line)
                         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
                         self.results.append([self.job_tests[worker_index], test_event])
                         self.job_tests[worker_index] = ''
                     elif event == 'job_begin':
                         self.jobs[worker_index] = test_event
                         if 'pid' in test_event:

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

 import sys
 import xml.sax.saxutils
 
 # Third-party modules
 import six
 
 # Local modules
 from ..event_builder import EventBuilder
+from ..build_exception import BuildError
 from .results_formatter import ResultsFormatter
 
 
 class XunitFormatter(ResultsFormatter):
     """Provides xUnit-style formatted output.
     """
 
     # Result mapping arguments
def _handle_failure(self, test_event):
                 '<failure type={} message={}><![CDATA[{}]]></failure>'.format(
                     XunitFormatter._quote_attribute(test_event["issue_class"]),
                     XunitFormatter._quote_attribute(message),
                     backtrace)
             ))
         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.
         """
         message = self._replace_invalid_xml(test_event["issue_message"])
         backtrace = self._replace_invalid_xml(
             "".join(test_event.get("issue_backtrace", [])))
 
         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),
                     backtrace)
             ))
         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.
         """
         if "test_name" in test_event:
             name = test_event["test_name"]
         else:
             name = test_event.get("test_filename", "<unknown test/filename>")