Bug 1048288 - Log test_end messages instead of errors to prevent useful messages about assertion counts from being buffered. r=ahal, a=test-only
authorChris Manchester <cmanchester@mozilla.com>
Wed, 06 Aug 2014 17:14:11 -0400
changeset 217476 ea403b4aa951f6b1362fcfc60ad552193cffb348
parent 217475 bfdc3bc16b17930457a2ec06d07e248754e2dcf6
child 217477 7e49a60f84f163f1a4914ffa87d948c51875bba7
push id515
push userraliiev@mozilla.com
push dateMon, 06 Oct 2014 12:51:51 +0000
treeherdermozilla-release@267c7a481bef [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersahal, test-only
bugs1048288
milestone33.0a2
Bug 1048288 - Log test_end messages instead of errors to prevent useful messages about assertion counts from being buffered. r=ahal, a=test-only
testing/mochitest/tests/SimpleTest/TestRunner.js
testing/mozbase/mozlog/mozlog/structured/formatters/tbplformatter.py
--- a/testing/mochitest/tests/SimpleTest/TestRunner.js
+++ b/testing/mochitest/tests/SimpleTest/TestRunner.js
@@ -105,22 +105,16 @@ function StructuredLogger(name) {
         }
         if (expected != status) {
             data.expected = expected;
         }
         if (extra !== null) {
             data.extra = extra;
         }
 
-        if (!this.testsStarted.pop(test)) {
-            this.error("Test '" + test + "' was ended more than once or never started. " +
-                       "Ended with this data: " + JSON.stringify(data));
-            return;
-        }
-
         this._logData("test_end", data);
     };
 
     this.suiteStart = function(tests, runinfo) {
         runinfo = typeof runinfo !== "undefined" ? runinfo : null;
 
         var data = {tests: tests};
         if (runinfo !== null) {
--- a/testing/mozbase/mozlog/mozlog/structured/formatters/tbplformatter.py
+++ b/testing/mozbase/mozlog/mozlog/structured/formatters/tbplformatter.py
@@ -43,28 +43,33 @@ class TbplFormatter(BaseMachFormatter):
             info_line = "TEST-INFO | expected %s\n" % data["expected"]
             return "\n".join([failure_line, info_line])
 
         return "TEST-%s | %s | %s %s\n" % (
             data["status"], self.id_str(data["test"]), data["subtest"],
             message)
 
     def test_end(self, data):
-        start_time = self.test_start_times.pop(self.test_id(data["test"]))
-        time = data["time"] - start_time
+        test_id = self.test_id(data["test"])
+        time_msg = ""
+
+        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:
             failure_line = "TEST-UNEXPECTED-%s | %s | %s" % (
-                data["status"], self.id_str(data["test"]),
-                data.get("message", ""))
-            info_line = "TEST-INFO expected %s | took %ims\n" % (data["expected"], time)
+                data["status"], test_id, data.get("message", ""))
+
+            info_line = "TEST-INFO expected %s%s\n" % (data["expected"], time_msg)
             return "\n".join([failure_line, info_line])
 
-        return "TEST-%s | %s | took %ims\n" % (
-            data["status"], self.id_str(data["test"]), time)
+        return "TEST-%s | %s%s\n" % (
+            data["status"], test_id, time_msg)
 
     def suite_end(self, data):
         start_time = self.suite_start_time
         time = int((data["time"] - start_time) / 1000)
 
         return "SUITE-END | took %is\n" % time
 
     def test_id(self, test_id):