Bug 1060366 - Log a message about the expected status when an unexpected status is encountered and no message is provided. r=jgraham
authorChris Manchester <cmanchester@mozilla.com>
Wed, 03 Sep 2014 10:03:29 -0400
changeset 203494 68655854f53d6e8117665febc7736aa5a27cdbf0
parent 203493 f5134820671ac0eecc952364abeafb1be86967db
child 203495 cfdcf950e403fc44a02a2e6877e2178027c336f6
push id27428
push usercbook@mozilla.com
push dateThu, 04 Sep 2014 13:00:04 +0000
treeherdermozilla-central@7bfd030e8fc8 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjgraham
bugs1060366
milestone35.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1060366 - Log a message about the expected status when an unexpected status is encountered and no message is provided. r=jgraham
testing/mozbase/mozlog/mozlog/structured/formatters/tbplformatter.py
testing/mozbase/mozlog/tests/test_structured.py
--- a/testing/mozbase/mozlog/mozlog/structured/formatters/tbplformatter.py
+++ b/testing/mozbase/mozlog/mozlog/structured/formatters/tbplformatter.py
@@ -69,16 +69,18 @@ class TbplFormatter(BaseFormatter):
     def test_status(self, data):
         message = "- " + data["message"] if "message" in data else ""
         if "stack" in data:
             message += "\n%s" % data["stack"]
         if message and message[-1] == "\n":
             message = message[:-1]
 
         if "expected" in data:
+            if not message:
+                message = "- expected %s\n" % data["expected"]
             failure_line = "TEST-UNEXPECTED-%s | %s | %s %s\n" % (
                 data["status"], self.id_str(data["test"]), data["subtest"],
                 message)
             if data["expected"] != "PASS":
                 info_line = "TEST-INFO | expected %s\n" % data["expected"]
                 return failure_line + info_line
             return failure_line
 
@@ -92,16 +94,18 @@ class TbplFormatter(BaseFormatter):
 
         if test_id in self.test_start_times:
             start_time = self.test_start_times.pop(test_id)
             time = data["time"] - start_time
             time_msg = "took %ims" % time
 
         if "expected" in data:
             message = data.get("message", "")
+            if not message:
+                message = "expected %s" % data["expected"]
             if "stack" in data:
                 message += "\n%s" % data["stack"]
             if message and message[-1] == "\n":
                 message = message[:-1]
 
             failure_line = "TEST-UNEXPECTED-%s | %s | %s\n" % (
                 data["status"], test_id, message)
 
--- a/testing/mozbase/mozlog/tests/test_structured.py
+++ b/testing/mozbase/mozlog/tests/test_structured.py
@@ -391,107 +391,151 @@ class TestTypeconversions(BaseStructured
         self.assertRaises(TypeError, self.logger.test_status, subtest="subtest2",
                           status="FAIL", expected="PASS")
         self.assertRaises(TypeError, self.logger.test_status, "test1", "subtest1",
                           "PASS", "FAIL", "message", "stack", {}, "unexpected")
         self.assertRaises(TypeError, self.logger.test_status, "test1", test="test2")
         self.logger.suite_end()
 
 
-class TestMachFormatter(unittest.TestCase):
+class FormatterTest(unittest.TestCase):
+
     def setUp(self):
-        self.logger = structuredlog.StructuredLogger("test")
+        self.position = 0
+        self.logger = structuredlog.StructuredLogger("test_%s" % type(self).__name__)
         self.output_file = StringIO.StringIO()
         self.handler = handlers.StreamHandler(
-            self.output_file, formatters.MachFormatter(disable_colors=True))
+            self.output_file, self.get_formatter())
         self.logger.add_handler(self.handler)
 
+    def set_position(self, pos=None):
+        if pos is None:
+            pos = self.output_file.tell()
+        self.position = pos
+
+    def get_formatter(self):
+        raise NotImplementedError("FormatterTest subclasses must implement get_formatter")
+
+    @property
+    def loglines(self):
+        self.output_file.seek(self.position)
+        return [line.rstrip() for line in self.output_file.readlines()]
+
+class TestTBPLFormatter(FormatterTest):
+
+    def get_formatter(self):
+        return formatters.TbplFormatter()
+
+    def test_unexpected_message(self):
+        self.logger.suite_start([])
+        self.logger.test_start("timeout_test")
+        self.logger.test_end("timeout_test",
+                             "TIMEOUT",
+                             message="timed out")
+        self.assertIn("TEST-UNEXPECTED-TIMEOUT | timeout_test | timed out",
+                      self.loglines)
+        self.logger.suite_end()
+
+    def test_default_unexpected_end_message(self):
+        self.logger.suite_start([])
+        self.logger.test_start("timeout_test")
+        self.logger.test_end("timeout_test",
+                             "TIMEOUT")
+        self.assertIn("TEST-UNEXPECTED-TIMEOUT | timeout_test | expected OK",
+                      self.loglines)
+        self.logger.suite_end()
+
+    def test_default_unexpected_status_message(self):
+        self.logger.suite_start([])
+        self.logger.test_start("timeout_test")
+        self.logger.test_status("timeout_test",
+                                "subtest",
+                                status="TIMEOUT")
+        self.assertIn("TEST-UNEXPECTED-TIMEOUT | timeout_test | subtest - expected PASS",
+                      self.loglines)
+        self.logger.test_end("timeout_test", "OK")
+        self.logger.suite_end()
+
+
+class TestMachFormatter(FormatterTest):
+
+    def get_formatter(self):
+        return formatters.MachFormatter(disable_colors=True)
+
     def test_summary(self):
         self.logger.suite_start([])
 
         #Some tests that pass
         self.logger.test_start("test1")
         self.logger.test_end("test1", status="PASS", expected="PASS")
 
         self.logger.test_start("test2")
         self.logger.test_end("test2", status="PASS", expected="TIMEOUT")
 
         self.logger.test_start("test3")
         self.logger.test_end("test3", status="FAIL", expected="PASS")
 
-        position = self.output_file.tell()
-
+        self.set_position()
         self.logger.suite_end()
 
-        self.output_file.seek(position)
-        lines = self.output_file.read().split("\n")
-
-        self.assertIn("Ran 3 tests", lines)
-        self.assertIn("Expected results: 1", lines)
-        self.assertIn("Unexpected results: 2 (FAIL: 1, PASS: 1)", lines)
-        self.assertNotIn("test1", lines)
-        self.assertIn("PASS expected TIMEOUT test2", lines)
-        self.assertIn("FAIL test3", lines)
+        self.assertIn("Ran 3 tests", self.loglines)
+        self.assertIn("Expected results: 1", self.loglines)
+        self.assertIn("Unexpected results: 2 (FAIL: 1, PASS: 1)", self.loglines)
+        self.assertNotIn("test1", self.loglines)
+        self.assertIn("PASS expected TIMEOUT test2", self.loglines)
+        self.assertIn("FAIL test3", self.loglines)
 
     def test_summary_subtests(self):
         self.logger.suite_start([])
 
         self.logger.test_start("test1")
         self.logger.test_status("test1", "subtest1", status="PASS")
         self.logger.test_status("test1", "subtest2", status="FAIL")
         self.logger.test_end("test1", status="OK", expected="OK")
 
         self.logger.test_start("test2")
         self.logger.test_status("test2", "subtest1", status="TIMEOUT", expected="PASS")
         self.logger.test_end("test2", status="TIMEOUT", expected="OK")
 
-        position = self.output_file.tell()
-
+        self.set_position()
         self.logger.suite_end()
 
-        self.output_file.seek(position)
-        lines = self.output_file.read().split("\n")
-
-        self.assertIn("Ran 5 tests (2 parents, 3 subtests)", lines)
-        self.assertIn("Expected results: 2", lines)
-        self.assertIn("Unexpected results: 3 (FAIL: 1, TIMEOUT: 2)", lines)
+        self.assertIn("Ran 5 tests (2 parents, 3 subtests)", self.loglines)
+        self.assertIn("Expected results: 2", self.loglines)
+        self.assertIn("Unexpected results: 3 (FAIL: 1, TIMEOUT: 2)", self.loglines)
 
     def test_summary_ok(self):
         self.logger.suite_start([])
 
         self.logger.test_start("test1")
         self.logger.test_status("test1", "subtest1", status="PASS")
         self.logger.test_status("test1", "subtest2", status="PASS")
         self.logger.test_end("test1", status="OK", expected="OK")
 
         self.logger.test_start("test2")
         self.logger.test_status("test2", "subtest1", status="PASS", expected="PASS")
         self.logger.test_end("test2", status="OK", expected="OK")
 
-        position = self.output_file.tell()
-
+        self.set_position()
         self.logger.suite_end()
 
-        self.output_file.seek(position)
-        lines = self.output_file.read().split("\n")
-
-        self.assertIn("OK", lines)
-        self.assertIn("Expected results: 5", lines)
-        self.assertIn("Unexpected results: 0", lines)
+        self.assertIn("OK", self.loglines)
+        self.assertIn("Expected results: 5", self.loglines)
+        self.assertIn("Unexpected results: 0", self.loglines)
 
 
 class TestCommandline(unittest.TestCase):
 
     def setUp(self):
         self.logfile = mozfile.NamedTemporaryFile()
 
     @property
     def loglines(self):
         self.logfile.seek(0)
-        return [line.strip() for line in self.logfile.readlines()]
+        return [line.rstrip() for line in self.logfile.readlines()]
 
     def test_setup_logging(self):
         parser = argparse.ArgumentParser()
         commandline.add_logging_group(parser)
         args = parser.parse_args(["--log-raw=-"])
         logger = commandline.setup_logging("test", args, {})
         self.assertEqual(len(logger.handlers), 1)