Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

--HG--
extra : commitid : 5hwiCNY4xAI
extra : rebase_source : 4f72ebe622669bb4f5df2c0be40d156e91c229f3

testing/mochitest/browser-harness.xul

@@ -11,6 +11,7 @@
         width="1024">
   <script type="application/javascript" src="chrome://mochikit/content/tests/SimpleTest/MozillaLogger.js"/>
   <script type="application/javascript" src="chrome://mochikit/content/tests/SimpleTest/LogController.js"/>
+  <script type="application/javascript" src="chrome://mochikit/content/tests/SimpleTest/StructuredLog.jsm"/>
   <script type="application/javascript" src="chrome://mochikit/content/tests/SimpleTest/TestRunner.js"/>
   <script type="application/javascript" src="chrome://mochikit/content/chrome-harness.js"/>
   <script type="application/javascript" src="chrome://mochikit/content/manifestLibrary.js" />
@@ -83,7 +84,7 @@
         delete this.fileLogger;
         return this.fileLogger = logger;
       },
-      structuredLogger: new StructuredLogger(),
+      structuredLogger: TestRunner.structuredLogger,
       dump: function (str) {
         this.structuredLogger.info(str);
 

testing/mochitest/harness.xul

@@ -11,6 +11,8 @@
           src="chrome://mochikit/content/tests/SimpleTest/LogController.js"/>
   <script type="text/javascript"
           src="chrome://mochikit/content/tests/SimpleTest/MemoryStats.js"/>
+  <script type="text/javascript"
+          src="chrome://mochikit/content/tests/SimpleTest/StructuredLog.jsm"/>
   <script type="text/javascript"
           src="chrome://mochikit/content/tests/SimpleTest/TestRunner.js"/>
   <script type="text/javascript"

testing/mochitest/jar.mn

@@ -34,6 +34,7 @@ mochikit.jar:
 * content/tests/SimpleTest/specialpowersAPI.js (../specialpowers/content/specialpowersAPI.js)
   content/tests/SimpleTest/setup.js (tests/SimpleTest/setup.js)
   content/tests/SimpleTest/SimpleTest.js (tests/SimpleTest/SimpleTest.js)
+  content/tests/SimpleTest/StructuredLog.jsm (../modules/StructuredLog.jsm)
   content/tests/SimpleTest/test.css (tests/SimpleTest/test.css)
   content/tests/SimpleTest/TestRunner.js (tests/SimpleTest/TestRunner.js)
   content/tests/SimpleTest/iframe-between-tests.html (tests/SimpleTest/iframe-between-tests.html)

testing/mochitest/runtests.py

@@ -149,6 +149,13 @@ class MessageLogger(object):
                     message['test'] = test[len(prefix):]
                     break
 
+    def _fix_message_format(self, message):
+        if 'message' in message:
+            if isinstance(message['message'], bytes):
+                message['message'] = message['message'].decode('utf-8', 'replace')
+            elif not isinstance(message['message'], unicode):
+                message['message'] = unicode(message['message'])
+
     def parse_line(self, line):
         """Takes a given line of input (structured or not) and returns a list of structured messages"""
         line = line.rstrip().decode("UTF-8", "replace")
@@ -172,6 +179,7 @@ class MessageLogger(object):
                     message=fragment,
                     unstructured=True)
             self._fix_test_name(message)
+            self._fix_message_format(message)
             messages.append(message)
 
         return messages
@@ -731,7 +739,7 @@ class MochitestUtilsMixin(object):
         testHost = "http://mochi.test:8888"
         testURL = "/".join([testHost, self.TEST_PATH])
 
-        if len(options.test_paths) == 1 :
+        if len(options.test_paths) == 1:
             if options.repeat > 0 and os.path.isfile(
                 os.path.join(
                     self.oldcwd,
@@ -2453,11 +2461,12 @@ class Mochitest(MochitestUtilsMixin):
         def countline(self, message):
             if message['action'] != 'log':
                 return message
+
             line = message['message']
             val = 0
             try:
                 val = int(line.split(':')[-1].strip())
-            except ValueError:
+            except (AttributeError, ValueError):
                 return message
 
             if "Passed:" in line:
@@ -2470,10 +2479,7 @@ class Mochitest(MochitestUtilsMixin):
 
         def fix_stack(self, message):
             if message['action'] == 'log' and self.stackFixerFunction:
-                message['message'] = self.stackFixerFunction(
-                    message['message'].encode(
-                        'utf-8',
-                        'replace'))
+                message['message'] = self.stackFixerFunction(message['message'])
             return message
 
         def record_last_test(self, message):

testing/mochitest/runtestsremote.py

@@ -2,12 +2,8 @@
 # License, v. 2.0. If a copy of the MPL was not distributed with this
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
-import base64
-import json
 import os
-import shutil
 import sys
-import tempfile
 import traceback
 
 sys.path.insert(
@@ -20,8 +16,6 @@ from remoteautomation import RemoteAutomation, fennecLogcatFilters
 from runtests import Mochitest, MessageLogger
 from mochitest_options import MochitestArgumentParser
 
-from manifestparser import TestManifest
-from manifestparser.filters import chunk_by_slice
 import devicemanager
 import mozinfo
 

testing/mochitest/server.js

@@ -668,6 +668,8 @@ function testListing(metadata, response)
         LINK({rel: "stylesheet",
               type: "text/css", href: "/static/harness.css"}
         ),
+        SCRIPT({type: "text/javascript",
+                 src: "/tests/SimpleTest/StructuredLog.jsm"}),
         SCRIPT({type: "text/javascript",
                  src: "/tests/SimpleTest/LogController.js"}),
         SCRIPT({type: "text/javascript",

testing/mochitest/tests/SimpleTest/TestRunner.js

@@ -68,228 +68,6 @@ function flattenArguments(lst/* ...*/) {
     return res;
 }
 
-/**
- * StructuredFormatter: Formatter class turning structured messages
- * into human-readable messages.
- */
-this.StructuredFormatter = function() {
-    this.testStartTimes = {};
-};
-
-StructuredFormatter.prototype.log = function(message) {
-  return message.message;
-};
-
-StructuredFormatter.prototype.suite_start = function(message) {
-    this.suiteStartTime = message.time;
-    return "SUITE-START | Running " +  message.tests.length + " tests";
-};
-
-StructuredFormatter.prototype.test_start = function(message) {
-    this.testStartTimes[message.test] = new Date().getTime();
-    return "TEST-START | " + message.test;
-};
-
-StructuredFormatter.prototype.test_status = function(message) {
-    var statusInfo = message.test + " | " + message.subtest +
-                    (message.message ? " | " + message.message : "");
-    if (message.expected) {
-        return "TEST-UNEXPECTED-" + message.status + " | " + statusInfo +
-               " - expected: " + message.expected;
-    } else {
-        return "TEST-" + message.status + " | " + statusInfo;
-    }
-};
-
-StructuredFormatter.prototype.test_end = function(message) {
-    var startTime = this.testStartTimes[message.test];
-    delete this.testStartTimes[message.test];
-    var statusInfo = message.test + (message.message ? " | " + String(message.message) : "");
-    var result;
-    if (message.expected) {
-        result = "TEST-UNEXPECTED-" + message.status + " | " + statusInfo +
-                 " - expected: " + message.expected;
-    } else {
-        return "TEST-" + message.status + " | " + statusInfo;
-    }
-    result = " | took " + message.time - startTime + "ms";
-};
-
-StructuredFormatter.prototype.suite_end = function(message) {
-    return "SUITE-END | took " + message.time - this.suiteStartTime + "ms";
-};
-
-/**
- * StructuredLogger: Structured logger class following the mozlog.structured protocol
- *
- *
-**/
-var VALID_ACTIONS = ['suite_start', 'suite_end', 'test_start', 'test_end', 'test_status', 'process_output', 'log'];
-// This delimiter is used to avoid interleaving Mochitest/Gecko logs.
-var LOG_DELIMITER = String.fromCharCode(0xe175) + String.fromCharCode(0xee31) + String.fromCharCode(0x2c32) + String.fromCharCode(0xacbf);
-
-function StructuredLogger(name) {
-    this.name = name;
-    this.testsStarted = [];
-    this.interactiveDebugger = false;
-    this.structuredFormatter = new StructuredFormatter();
-
-    /* test logs */
-
-    this.testStart = function(test) {
-        var data = {test: test};
-        this._logData("test_start", data);
-    };
-
-    this.testStatus = function(test, subtest, status, expected="PASS", message=null, stack=null) {
-        // Bugfix for assertions not passing an assertion name
-        if (subtest === null || subtest === undefined) {
-            subtest = "undefined assertion name";
-        }
-
-        var data = {test: test, subtest: subtest, status: status};
-
-        if (message) {
-            data.message = String(message);
-        }
-        if (expected != status && status != 'SKIP') {
-            data.expected = expected;
-        }
-        if (stack) {
-            data.stack = stack;
-        }
-
-        this._logData("test_status", data);
-    };
-
-    this.testEnd = function(test, status, expected="OK", message=null, extra=null) {
-        var data = {test: test, status: status};
-
-        if (message !== null) {
-            data.message = String(message);
-        }
-        if (expected != status) {
-            data.expected = expected;
-        }
-        if (extra !== null) {
-            data.extra = extra;
-        }
-
-        this._logData("test_end", data);
-    };
-
-    this.suiteStart = function(tests, runinfo) {
-        runinfo = typeof runinfo !== "undefined" ? runinfo : null;
-
-        var data = {tests: tests};
-        if (runinfo !== null) {
-            data.runinfo = runinfo;
-        }
-
-        this._logData("suite_start", data);
-    };
-
-    this.suiteEnd = function() {
-        this._logData("suite_end");
-    };
-
-    this.testStart = function(test) {
-        this.testsStarted.push(test);
-        var data = {test: test};
-        this._logData("test_start", data);
-    };
-
-    /* log action: human readable logs */
-
-    this._log = function(level, message) {
-        // Coercing the message parameter to a string, in case an invalid value is passed.
-        message = String(message);
-        var data = {level: level, message: message};
-        this._logData('log', data);
-    };
-
-    this.debug = function(message) {
-        this._log('DEBUG', message);
-    };
-
-    this.info = function(message) {
-        this._log('INFO', message);
-    };
-
-    this.warning = function(message) {
-        this._log('WARNING', message);
-    };
-
-    this.error = function(message) {
-        this._log("ERROR", message);
-    };
-
-    this.critical = function(message) {
-        this._log('CRITICAL', message);
-    };
-
-    /* Special mochitest messages for deactivating/activating buffering */
-
-    this.deactivateBuffering = function() {
-        this._logData("buffering_off");
-    };
-    this.activateBuffering = function() {
-        this._logData("buffering_on");
-    };
-
-    /* dispatches a log to handlers */
-
-    this._logData = function(action, data) {
-        data = typeof data !== "undefined" ? data : null;
-
-        if (data === null) {
-            data = {};
-        }
-
-        var allData = {action: action,
-                       time: new Date().getTime(),
-                       thread: "",
-                       // This is a directive to python to format these messages
-                       // for compatibility with mozharness. This can be removed
-                       // with the MochitestFormatter (see bug 1045525).
-                       js_source: "TestRunner",
-                       pid: null,
-                       source: this.name};
-
-        for (var attrname in data) {
-            allData[attrname] = data[attrname];
-        }
-
-        this._dumpMessage(allData);
-    };
-
-    this._dumpMessage = function(message) {
-        var str;
-        if (this.interactiveDebugger && !message.action.startsWith("buffering_")) {
-            str = this.structuredFormatter[message.action](message);
-        } else {
-            str = LOG_DELIMITER + JSON.stringify(message) + LOG_DELIMITER;
-        }
-
-        // BUGFIX: browser-chrome tests doesn't use LogController
-        if (Object.keys(LogController.listeners).length !== 0) {
-            LogController.log(str);
-        } else {
-            dump('\n' + str + '\n');
-        }
-
-        // Checking for error messages
-        if (message.expected || (message.level && message.level === "ERROR")) {
-            TestRunner.failureHandler();
-        }
-    };
-
-    /* Message validation. Only checking the action for now */
-    this.validMessage = function(message) {
-        return message.action !== undefined && VALID_ACTIONS.indexOf(message.action) >= 0;
-    };
-}
-
 /**
  * TestRunner: A test runner for SimpleTest
  * TODO:
@@ -318,6 +96,7 @@ TestRunner.dumpAboutMemoryAfterTest = false;
 TestRunner.dumpDMDAfterTest = false;
 TestRunner.slowestTestTime = 0;
 TestRunner.slowestTestURL = "";
+TestRunner.interactiveDebugger = false;
 
 TestRunner._expectingProcessCrash = false;
 
@@ -429,8 +208,48 @@ TestRunner.generateFailureList = function () {
 
 /**
  * If logEnabled is true, this is the logger that will be used.
-**/
-TestRunner.structuredLogger = new StructuredLogger('mochitest');
+ **/
+
+// A log callback for StructuredLog.jsm
+TestRunner._dumpMessage = function(message) {
+  // This delimiter is used to avoid interleaving Mochitest/Gecko logs.
+  var LOG_DELIMITER = String.fromCharCode(0xe175) + String.fromCharCode(0xee31) + String.fromCharCode(0x2c32) + String.fromCharCode(0xacbf);
+  var _structuredFormatter;
+  var str;
+
+  // This is a directive to python to format these messages
+  // for compatibility with mozharness. This can be removed
+  // with the MochitestFormatter (see bug 1045525).
+  message.js_source = 'TestRunner.js'
+
+  if (TestRunner.interactiveDebugger) {
+    if (!_structuredFormatter) {
+      _structuredFormatter = new StructuredFormatter();
+    }
+    str = _structuredFormatter[message.action](message);
+  } else {
+    str = LOG_DELIMITER + JSON.stringify(message) + LOG_DELIMITER;
+  }
+  // BUGFIX: browser-chrome tests don't use LogController
+  if (Object.keys(LogController.listeners).length !== 0) {
+    LogController.log(str);
+  } else {
+    dump('\n' + str + '\n');
+  }
+  // Checking for error messages
+  if (message.expected || message.level === "ERROR") {
+    TestRunner.failureHandler();
+  }
+};
+
+// From https://dxr.mozilla.org/mozilla-central/source/testing/modules/StructuredLog.jsm
+TestRunner.structuredLogger = new StructuredLogger('mochitest', TestRunner._dumpMessage);
+TestRunner.structuredLogger.deactivateBuffering = function() {
+    TestRunner.structuredLogger._logData("buffering_off");
+};
+TestRunner.structuredLogger.activateBuffering = function() {
+    TestRunner.structuredLogger._logData("buffering_on");
+};
 
 TestRunner.log = function(msg) {
     if (TestRunner.logEnabled) {

testing/mochitest/tests/SimpleTest/setup.js

@@ -143,7 +143,7 @@ if (params.dumpDMDAfterTest) {
 }
 
 if (params.interactiveDebugger) {
-  TestRunner.structuredLogger.interactiveDebugger = true;
+  TestRunner.interactiveDebugger = true;
 }
 
 if (params.maxTimeouts) {

testing/mochitest/tests/index.html

@@ -1,6 +1,7 @@
 <html>
 <head>
     <!-- This harness does not work locally in Safari -->
+    <script type="application/javascript" src="SimpleTest/StructuredLog.jsm"></script>
     <script type="text/javascript" src="../MochiKit/MochiKit.js"></script>
     <script type="text/javascript" src="SimpleTest/MemoryStats.js"></script>
     <script type="text/javascript" src="SimpleTest/TestRunner.js"></script>

testing/modules/StructuredLog.jsm

@@ -5,7 +5,8 @@
 "use strict";
 
 this.EXPORTED_SYMBOLS = [
-  "StructuredLogger"
+  "StructuredLogger",
+  "StructuredFormatter"
 ];
 
 /**
@@ -22,25 +23,30 @@ this.EXPORTED_SYMBOLS = [
  *        These will each be called with the complete object to log as an
  *        argument.
  */
-this.StructuredLogger = function (name, dumpFun=dump, mutators=[]) {
+this.StructuredLogger = function(name, dumpFun=dump, mutators=[]) {
   this.name = name;
   this._dumpFun = dumpFun;
   this._mutatorFuns = mutators;
-  this._runningTests = new Set();
 }
 
 /**
  * Log functions producing messages in the format specified by mozlog
  */
-StructuredLogger.prototype.testStart = function (test) {
-  this._runningTests.add(test);
-  let data = {test: test};
+StructuredLogger.prototype = {
+  testStart: function (test) {
+    var data = {test: test};
     this._logData("test_start", data);
-}
+  },
 
-StructuredLogger.prototype.testStatus = function (test, subtest, status, expected="PASS",
+  testStatus: function (test, subtest, status, expected="PASS",
                         message=null, stack=null, extra=null) {
-  let data = {
+
+    if (subtest === null || subtest === undefined) {
+      // Fix for assertions that don't pass in a name
+      subtest = "undefined assertion name";
+    }
+
+    var data = {
       test: test,
       subtest: subtest,
       status: status,
@@ -50,7 +56,7 @@ StructuredLogger.prototype.testStatus = function (test, subtest, status, expecte
       data.expected = expected;
     }
     if (message !== null) {
-    data.message = message;
+      data.message = String(message);
     }
     if (stack !== null) {
       data.stack = stack;
@@ -60,17 +66,16 @@ StructuredLogger.prototype.testStatus = function (test, subtest, status, expecte
     }
 
     this._logData("test_status", data);
-}
+  },
 
-StructuredLogger.prototype.testEnd = function (test, status, expected="OK", message=null,
-                                               stack=null, extra=null) {
-  let data = {test: test, status: status};
+  testEnd: function (test, status, expected="OK", message=null, stack=null, extra=null) {
+    var data = {test: test, status: status};
 
     if (expected != status && status != "SKIP") {
       data.expected = expected;
     }
     if (message !== null) {
-    data.message = message;
+      data.message = String(message);
     }
     if (stack !== null) {
       data.stack = stack;
@@ -79,39 +84,32 @@ StructuredLogger.prototype.testEnd = function (test, status, expected="OK", mess
       data.extra = extra;
     }
 
-  if (!this._runningTests.has(test)) {
-    this.error("Test \"" + test + "\" was ended more than once or never started. " +
-               "Ended with this data: " + JSON.stringify(data));
-    return;
-  }
-
-  this._runningTests.delete(test);
     this._logData("test_end", data);
-}
+  },
 
-StructuredLogger.prototype.suiteStart = function (tests, runinfo=null) {
-
-  let data = {tests: tests};
+  suiteStart: function (tests, runinfo=null) {
+    var data = {tests: tests};
     if (runinfo !== null) {
       data.runinfo = runinfo;
     }
 
     this._logData("suite_start", data);
-};
+  },
 
-StructuredLogger.prototype.suiteEnd = function () {
+  suiteEnd: function () {
     this._logData("suite_end");
-};
+  },
 
-/**
+
+  /**
    * Unstructured logging functions. The "extra" parameter can always by used to
    * log suite specific data. If a "stack" field is provided it is logged at the
    * top level of the data object for the benefit of mozlog's formatters.
    */
-StructuredLogger.prototype.log = function (level, message, extra=null) {
-  let data = {
+  log: function (level, message, extra=null) {
+    var data = {
       level: level,
-    message: message,
+      message: String(message),
     };
 
     if (extra !== null) {
@@ -122,30 +120,30 @@ StructuredLogger.prototype.log = function (level, message, extra=null) {
     }
 
     this._logData("log", data);
-}
+  },
 
-StructuredLogger.prototype.debug = function (message, extra=null) {
+  debug: function (message, extra=null) {
     this.log("DEBUG", message, extra);
-}
+  },
 
-StructuredLogger.prototype.info = function (message, extra=null) {
+  info: function (message, extra=null) {
     this.log("INFO", message, extra);
-}
+  },
 
-StructuredLogger.prototype.warning = function (message, extra=null) {
+  warning: function (message, extra=null) {
     this.log("WARNING", message, extra);
-}
+  },
 
-StructuredLogger.prototype.error = function (message, extra=null) {
+  error: function (message, extra=null) {
     this.log("ERROR", message, extra);
-}
+  },
 
-StructuredLogger.prototype.critical = function (message, extra=null) {
+  critical: function (message, extra=null) {
     this.log("CRITICAL", message, extra);
-}
+  },
 
-StructuredLogger.prototype._logData = function (action, data={}) {
-  let allData = {
+  _logData: function (action, data={}) {
+    var allData = {
       action: action,
       time: Date.now(),
       thread: null,
@@ -153,17 +151,70 @@ StructuredLogger.prototype._logData = function (action, data={}) {
       source: this.name
     };
 
-  for (let field in data) {
+    for (var field in data) {
       allData[field] = data[field];
     }
 
-  for (let fun of this._mutatorFuns) {
+    for (var fun of this._mutatorFuns) {
       fun(allData);
     }
 
-  this._dumpMessage(allData);
+    this._dumpFun(allData);
+  }
+};
+
+
+/**
+ * StructuredFormatter: Formatter class turning structured messages
+ * into human-readable messages.
+ */
+this.StructuredFormatter = function() {
+    this.testStartTimes = {};
+};
+
+StructuredFormatter.prototype = {
+
+  log: function(message) {
+    return message.message;
+  },
+
+  suite_start: function(message) {
+    this.suiteStartTime = message.time;
+    return "SUITE-START | Running " +  message.tests.length + " tests";
+  },
+
+  test_start: function(message) {
+    this.testStartTimes[message.test] = new Date().getTime();
+    return "TEST-START | " + message.test;
+  },
+
+  test_status: function(message) {
+    var statusInfo = message.test + " | " + message.subtest +
+                    (message.message ? " | " + message.message : "");
+    if (message.expected) {
+        return "TEST-UNEXPECTED-" + message.status + " | " + statusInfo +
+               " - expected: " + message.expected;
+    } else {
+        return "TEST-" + message.status + " | " + statusInfo;
+    }
+  },
+
+  test_end: function(message) {
+    var startTime = this.testStartTimes[message.test];
+    delete this.testStartTimes[message.test];
+    var statusInfo = message.test + (message.message ? " | " + String(message.message) : "");
+    var result;
+    if (message.expected) {
+        result = "TEST-UNEXPECTED-" + message.status + " | " + statusInfo +
+                 " - expected: " + message.expected;
+    } else {
+        return "TEST-" + message.status + " | " + statusInfo;
+    }
+    result = " | took " + message.time - startTime + "ms";
+  },
+
+  suite_end: function(message) {
+    return "SUITE-END | took " + message.time - this.suiteStartTime + "ms";
+  }
 };
 
-StructuredLogger.prototype._dumpMessage = function (message) {
-  this._dumpFun(JSON.stringify(message));
-}

testing/modules/moz.build

@@ -15,3 +15,5 @@ TESTING_JS_MODULES += [
     'StructuredLog.jsm',
     'TestUtils.jsm',
 ]
+
+TEST_HARNESS_FILES.testing.mochitest.tests.SimpleTest += ['StructuredLog.jsm']

testing/modules/tests/xpcshell/test_structuredlog.js

@@ -7,7 +7,7 @@ function run_test () {
   let testBuffer = [];
 
   let appendBuffer = function (msg) {
-    testBuffer.push(msg);
+    testBuffer.push(JSON.stringify(msg));
   }
 
   let assertLastMsg = function (refData) {
@@ -48,14 +48,12 @@ function run_test () {
 
   // Test end / start actions
   logger.testStart("aTest");
-  ok(logger._runningTests.has("aTest"));
   assertLastMsg({
     test: "aTest",
     action: "test_start",
   });
 
   logger.testEnd("aTest", "OK");
-  ok(!logger._runningTests.has("aTest"));
   assertLastMsg({
     test: "aTest",
     action: "test_end",
@@ -93,20 +91,6 @@ function run_test () {
     status: "SKIP"
   });
 
-  // Ending a test twice logs an error.
-  logger.testEnd("aTest", "PASS");
-  assertLastMsg({
-    action: "log",
-    level: "ERROR"
-  });
-
-  // Ending a test than never started logs an error.
-  logger.testEnd("errantTest", "PASS");
-  assertLastMsg({
-    action: "log",
-    level: "ERROR"
-  });
-
   logger.testStatus("aTest", "foo", "PASS", "PASS", "Passed test");
   ok(!JSON.parse(testBuffer[testBuffer.length - 1]).hasOwnProperty("expected"));
   assertLastMsg({

testing/xpcshell/head.js

@@ -42,7 +42,7 @@ var _add_params = function (params) {
 };
 
 var _dumpLog = function (raw_msg) {
-  dump("\n" + raw_msg + "\n");
+  dump("\n" + JSON.stringify(raw_msg) + "\n");
 }
 
 var _LoggerClass = Components.utils.import("resource://testing-common/StructuredLog.jsm", null).StructuredLogger;