Bug 1055679 - Log stacks and messages separately in moztest's unittest adapter and include stacks in mozlog's test_end.;r=jgraham

testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py

@@ -170,11 +170,19 @@ class MachFormatter(base.BaseFormatter):
     def test_end(self, data):
         subtests = self._get_subtest_data(data)
         unexpected = subtests["unexpected"]
+
+        message = data.get("message", "")
+        if "stack" in data:
+            stack = data["stack"]
+            if stack and stack[-1] != "\n":
+                stack += "\n"
+            message = stack + message
+
         if "expected" in data:
             parent_unexpected = True
             expected_str = ", expected %s" % data["expected"]
             unexpected.append((None, data["status"], data["expected"],
-                               data.get("message", "")))
+                               message))
         else:
             parent_unexpected = False
             expected_str = ""

testing/mozbase/mozlog/mozlog/structured/formatters/tbplformatter.py

@@ -84,7 +84,9 @@ class TbplFormatter(BaseFormatter):
     def test_end(self, data):
         test_id = self.test_id(data["test"])
         time_msg = ""
-
+        message = data.get("message", "")
+        if "stack" in data:
+            message += "\n%s" % data["stack"]
         if test_id in self.test_start_times:
             start_time = self.test_start_times.pop(test_id)
             time = data["time"] - start_time
@@ -92,7 +94,7 @@ class TbplFormatter(BaseFormatter):
 
         if "expected" in data:
             failure_line = "TEST-UNEXPECTED-%s | %s | %s" % (
-                data["status"], test_id, data.get("message", ""))
+                data["status"], test_id, message)
 
             info_line = "TEST-INFO expected %s%s\n" % (data["expected"], time_msg)
             return "\n".join([failure_line, info_line])

testing/mozbase/moztest/moztest/adapters/unit.py

@@ -3,7 +3,9 @@
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
 import unittest
+import sys
 import time
+import traceback
 
 try:
     from unittest import TextTestResult
@@ -51,21 +53,50 @@ class StructuredTestResult(TextTestResult):
         # logging protocol, this action should only be called once.
         pass
 
+    def _extract_err_message(self, err):
+        # Format an exception message in the style of unittest's _exc_info_to_string
+        # while maintaining a division between a traceback and a message.
+        exc_ty, val, _ = err
+        exc_msg = "".join(traceback.format_exception_only(exc_ty, val))
+        if self.buffer:
+            output_msg = "\n".join([sys.stdout.getvalue(), sys.stderr.getvalue()])
+            return "\n".join([exc_msg, output_msg])
+        return exc_msg
+
+    def _extract_stacktrace(self, err, test):
+        # Format an exception stack in the style of unittest's _exc_info_to_string
+        # while maintaining a division between a traceback and a message.
+        # This is mostly borrowed from unittest.result._exc_info_to_string.
+
+        exctype, value, tb = err
+        while tb and self._is_relevant_tb_level(tb):
+            tb = tb.tb_next
+        # Header usually included by print_exception
+        lines = ["Traceback (most recent call last):\n"]
+        if exctype is test.failureException:
+            length = self._count_relevant_tb_levels(tb)
+            lines += traceback.format_tb(tb, length)
+        else:
+            lines += traceback.format_tb(tb)
+        return "".join(lines)
+
     def addError(self, test, err):
         self.errors.append((test, self._exc_info_to_string(err, test)))
         extra = self.call_callbacks(test, "ERROR")
         self.logger.test_end(test.id(),
                              "ERROR",
-                             message=self._exc_info_to_string(err, test),
+                             message=self._extract_err_message(err),
                              expected="PASS",
+                             stack=self._extract_stacktrace(err, test),
                              extra=extra)
 
     def addFailure(self, test, err):
         extra = self.call_callbacks(test, "ERROR")
         self.logger.test_end(test.id(),
                             "FAIL",
-                             message=self._exc_info_to_string(err, test),
+                             message=self._extract_err_message(err),
                              expected="PASS",
+                             stack=self._extract_stacktrace(err, test),
                              extra=extra)
 
     def addSuccess(self, test):
@@ -75,8 +106,9 @@ class StructuredTestResult(TextTestResult):
         extra = self.call_callbacks(test, "ERROR")
         self.logger.test_end(test.id(),
                             "FAIL",
-                             message=self._exc_info_to_string(err, test),
+                             message=self._extract_err_message(err),
                              expected="FAIL",
+                             stack=self._extract_stacktrace(err, test),
                              extra=extra)
 
     def addUnexpectedSuccess(self, test):