Bug 1048288 - Log test_end messages instead of errors to prevent useful messages about assertion counts from being buffered.;r=ahal

testing/mochitest/tests/SimpleTest/TestRunner.js

@@ -164,12 +164,6 @@ function StructuredLogger(name) {
             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);
     };
 

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

@@ -48,18 +48,23 @@ class TbplFormatter(BaseFormatter):
             message)
 
     def test_end(self, data):
-        start_time = self.test_start_times.pop(self.test_id(data["test"]))
+        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