Bug 1293250 - Make reftest log generation less magical, r=ahal
authorJames Graham <james@hoppipolla.co.uk>
Mon, 08 Aug 2016 17:48:39 +0100
changeset 400399 4ad88cfd05b50399ab02a3814361c9cebacffefd
parent 400398 782f590541b8173cd1b073a88732afa601f05715
child 400400 e225f606ad70067ab50cff51879b59be4e98659e
push id26138
push usergszorc@mozilla.com
push dateSat, 13 Aug 2016 03:04:36 +0000
reviewersahal
bugs1293250
milestone51.0a1
Bug 1293250 - Make reftest log generation less magical, r=ahal Ensure that the first line of the log for failing tests is identical to one that would be produced by the tbplformatter from mozlog. This means that treeherder will be able to sucessfully cross-match error lines. Also make the data structures used for storing screenshots identical between reftests and web-platform-tests so that we can start to move toward removing the reftest-specific codepath here. MozReview-Commit-ID: FZQXLjj9Ejv
layout/tools/reftest/output.py
layout/tools/reftest/reftest.jsm
testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
--- a/layout/tools/reftest/output.py
+++ b/layout/tools/reftest/output.py
@@ -32,44 +32,40 @@ class ReftestFormatter(TbplFormatter):
 
     def log(self, data):
         prefix = "%s |" % data['level'].upper()
         return "%s %s\n" % (prefix, data['message'])
 
     def test_end(self, data):
         extra = data.get('extra', {})
         status = data['status']
+        test = data['test']
 
         status_msg = "TEST-"
         if 'expected' in data:
             status_msg += "UNEXPECTED-%s" % status
         else:
             if status != "PASS":
                 status_msg += "KNOWN-"
             status_msg += status
             if extra.get('status_msg') == 'Random':
                 status_msg += "(EXPECTED RANDOM)"
-        test = self.id_str(data['test'])
-        if 'message' in data:
-            status_details = data['message']
-        elif isinstance(data['test'], tuple):
-            status_details = 'image comparison ({})'.format(data['test'][1])
-        else:
-            status_details = '(LOAD ONLY)'
+
+
+        output_text = "%s | %s | %s" % (status_msg, test, data.get("message", ""))
 
-        output_text = "%s | %s | %s" % (status_msg, test, status_details)
-        if 'differences' in extra:
-            diff_msg = (", max difference: %(max_difference)s"
-                        ", number of differing pixels: %(differences)s") % extra
-            diagnostic_data = ("REFTEST   IMAGE 1 (TEST): %(image1)s\n"
-                               "REFTEST   IMAGE 2 (REFERENCE): %(image2)s") % extra
-            output_text += '%s\n%s' % (diff_msg, diagnostic_data)
-        elif "image1" in extra:
-            diagnostic_data = "REFTEST   IMAGE: %(image1)s" % extra
-            output_text += '\n%s' % diagnostic_data
+        if "reftest_screenshots" in extra:
+            screenshots = extra["reftest_screenshots"]
+            if len(screenshots) == 3:
+                output_text += ("\nREFTEST   IMAGE 1 (TEST): %s\n"
+                                "REFTEST   IMAGE 2 (REFERENCE): %s") % (screenshots[0]["screenshot"],
+                                                                         screenshots[2]["screenshot"])
+            elif len(screenshots) == 1:
+                output_text += "\nREFTEST   IMAGE: %(image1)s" % screenshots[0]["screenshot"]
+
 
         output_text += "\nREFTEST TEST-END | %s" % test
         return "%s\n" % output_text
 
     def process_output(self, data):
         return "%s\n" % data["data"]
 
     def suite_end(self, data):
@@ -94,21 +90,16 @@ class ReftestFormatter(TbplFormatter):
                       "%(AssertionKnown)s known asserts, " +
                       "%(Random)s random, " +
                       "%(Skip)s skipped, " +
                       "%(Slow)s slow)") % summary)
         lines = ["REFTEST INFO | %s" % s for s in lines]
         lines.append("REFTEST SUITE-END | Shutdown")
         return "INFO | Result summary:\n{}\n".format('\n'.join(lines))
 
-    def id_str(self, test_id):
-        if isinstance(test_id, basestring):
-            return test_id
-        return test_id[0]
-
 
 class OutputHandler(object):
     """Process the output of a process during a test run and translate
     raw data logged from reftest.js to an appropriate structured log action,
     where applicable.
     """
 
     def __init__(self, log, utilityPath, symbolsPath=None):
--- a/layout/tools/reftest/reftest.jsm
+++ b/layout/tools/reftest/reftest.jsm
@@ -1696,29 +1696,37 @@ function RecordResult(testRunTime, error
                     failures.push("failed reftest-opaque-layer: " + gFailedOpaqueLayerMessages.join(", "));
                 }
                 if (gFailedAssignedLayer) {
                     failures.push("failed reftest-assigned-layer: " + gFailedAssignedLayerMessages.join(", "));
                 }
                 var failureString = failures.join(", ");
                 logger.testEnd(gURLs[0].identifier, output.s[0], output.s[1], failureString, null, extra);
             } else {
+                var message = "image comparison";
                 if (!test_passed && expected == EXPECTED_PASS ||
                     !test_passed && expected == EXPECTED_FUZZY ||
                     test_passed && expected == EXPECTED_FAIL) {
                     if (!equal) {
                         extra.max_difference = maxDifference.value;
                         extra.differences = differences;
+                        extra.reftest_screenshots = [
+                            {url:gURLs[0].identifier[0], screenshot: gCanvas1.toDataURL()},
+                            gURLs[0].identifier[1],
+                            {url:gURLs[0].identifier[1], screenshot: gCanvas2.toDataURL()}
+                        ];
                         extra.image1 = gCanvas1.toDataURL();
                         extra.image2 = gCanvas2.toDataURL();
+                        message += (", max difference: " + extra.max_difference +
+                                    ", number of differing pixels: " + differences);
                     } else {
                         extra.image1 = gCanvas1.toDataURL();
                     }
                 }
-                logger.testEnd(gURLs[0].identifier, output.s[0], output.s[1], null, null, extra);
+                logger.testEnd(gURLs[0].identifier, output.s[0], output.s[1], message, null, extra);
 
                 if (gURLs[0].prefSettings1.length == 0) {
                     UpdateCanvasCache(gURLs[0].url1, gCanvas1);
                 }
                 if (gURLs[0].prefSettings2.length == 0) {
                     UpdateCanvasCache(gURLs[0].url2, gCanvas2);
                 }
             }
--- a/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
@@ -82,17 +82,17 @@ class TbplFormatter(BaseFormatter):
 
     @output_subtests
     def process_exit(self, data):
         return "TEST-INFO | %s: %s\n" % (data['process'],
                                          strstatus(data['exitcode']))
 
     @output_subtests
     def crash(self, data):
-        id = self.id_str(data["test"]) if "test" in data else "pid: %s" % data["process"]
+        id = data["test"] if "test" in data else "pid: %s" % data["process"]
 
         signature = data["signature"] if data["signature"] else "unknown top frame"
         rv = ["PROCESS-CRASH | %s | application crashed [%s]" % (id, signature)]
 
         if data.get("minidump_path"):
             rv.append("Crash dump filename: %s" % data["minidump_path"])
 
         if data.get("stackwalk_stderr"):
@@ -116,17 +116,17 @@ class TbplFormatter(BaseFormatter):
 
     def suite_start(self, data):
         self.suite_start_time = data["time"]
         return "SUITE-START | Running %i tests\n" % len(data["tests"])
 
     def test_start(self, data):
         self.test_start_times[self.test_id(data["test"])] = data["time"]
 
-        return "TEST-START | %s\n" % self.id_str(data["test"])
+        return "TEST-START | %s\n" % data["test"]
 
     def test_status(self, data):
         if self.compact:
             if "expected" in data:
                 rv = []
                 rv.append(self._format_subtests(data.get("component"), subtract_context=True))
                 rv.extend(self._format_status(item) for item in self.buffer)
                 rv.append(self._format_status(data))
@@ -144,25 +144,25 @@ class TbplFormatter(BaseFormatter):
             message += "\n%s" % data["stack"]
         if message and message[-1] == "\n":
             message = message[:-1]
 
         if "expected" in data:
             if not message:
                 message = "- expected %s" % data["expected"]
             failure_line = "TEST-UNEXPECTED-%s | %s | %s %s\n" % (
-                data["status"], self.id_str(data["test"]), data["subtest"],
+                data["status"], 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
 
         return "TEST-%s | %s | %s %s\n" % (
-            data["status"], self.id_str(data["test"]), data["subtest"],
+            data["status"], data["test"], data["subtest"],
             message)
 
     def test_end(self, data):
         rv = []
         if self.compact and self.subtests_count:
             print_context = "expected" in data
             rv.append(self._format_subtests(data.get("component"),
                                             subtract_context=print_context))
@@ -182,28 +182,38 @@ class TbplFormatter(BaseFormatter):
             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]
 
+            extra = data.get("extra", {})
+            if "reftest_screenshots" in extra:
+                screenshots = extra["reftest_screenshots"]
+                if len(screenshots) == 3:
+                     message += ("\nREFTEST   IMAGE 1 (TEST): %s\n"
+                                 "REFTEST   IMAGE 2 (REFERENCE): %s") % (screenshots[0]["screenshot"],
+                                                                         screenshots[2]["screenshot"])
+                elif len(screenshots) == 1:
+                    message += "\nREFTEST   IMAGE: %(image1)s" % screenshots[0]["screenshot"]
+
             failure_line = "TEST-UNEXPECTED-%s | %s | %s\n" % (
-                data["status"], self.id_str(test_id), message)
+            data["status"], test_id, message)
 
             if data["expected"] not in ("PASS", "OK"):
                 expected_msg = "expected %s | " % data["expected"]
             else:
                 expected_msg = ""
             info_line = "TEST-INFO %s%s\n" % (expected_msg, duration_msg)
 
             return failure_line + info_line
 
-        sections = ["TEST-%s" % data['status'], self.id_str(test_id)]
+        sections = ["TEST-%s" % data['status'], test_id]
         if duration_msg:
             sections.append(duration_msg)
         rv.append(' | '.join(sections) + '\n')
         return "".join(rv)
 
     def suite_end(self, data):
         start_time = self.suite_start_time
         time = int((data["time"] - start_time) / 1000)
@@ -211,21 +221,15 @@ class TbplFormatter(BaseFormatter):
         return "SUITE-END | took %is\n" % time
 
     def test_id(self, test_id):
         if isinstance(test_id, (str, unicode)):
             return test_id
         else:
             return tuple(test_id)
 
-    def id_str(self, test_id):
-        if isinstance(test_id, (str, unicode)):
-            return test_id
-        else:
-            return " ".join(test_id)
-
     @output_subtests
     def valgrind_error(self, data):
         rv = "TEST-UNEXPECTED-VALGRIND-ERROR | " + data['primary'] + "\n"
         for line in data['secondary']:
             rv = rv + line + "\n"
 
         return rv