Bug 916265 - Implement a jsm to output structured log messages.;r=ted
authorChris Manchester <cmanchester@mozilla.com>
Mon, 21 Jul 2014 14:34:01 -0700
changeset 195414 e8501234d9e1ad16f4487c126e277cf8cfa456e3
parent 195413 40d096f86523a35dd31bc6db4194bb5dfcba0b8c
child 195415 7a5b3439faa73e70f21c9b080e7e96bfec35ee24
push id27182
push useremorley@mozilla.com
push dateTue, 22 Jul 2014 16:21:27 +0000
treeherdermozilla-central@fe7c119a55e2 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersted
bugs916265
milestone33.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 916265 - Implement a jsm to output structured log messages.;r=ted
testing/modules/StructuredLog.jsm
testing/modules/moz.build
testing/modules/tests/xpcshell/test_structuredlog.js
testing/modules/tests/xpcshell/xpcshell.ini
new file mode 100644
--- /dev/null
+++ b/testing/modules/StructuredLog.jsm
@@ -0,0 +1,165 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * 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/. */
+
+"use strict";
+
+this.EXPORTED_SYMBOLS = [
+  "StructuredLogger"
+];
+
+/**
+ * TestLogger: Logger class generating messages compliant with the
+ * structured logging protocol for tests exposed by the mozlog.structured
+ *
+ * @param name
+ *        The name of the logger to instantiate.
+ * @param dumpFun
+ *        An underlying function to be used to log raw messages. This function
+ *        will receive the complete serialized json string to log.
+ * @param mutators
+ *        An array of functions used to add global context to log messages.
+ *        These will each be called with the complete object to log as an
+ *        argument.
+ */
+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.structured
+ */
+StructuredLogger.prototype.testStart = function (test) {
+  this._runningTests.add(test);
+  let data = {test: test};
+  this._logData("test_start", data);
+}
+
+StructuredLogger.prototype.testStatus = function (test, subtest, status, expected="PASS",
+                                                  message=null, stack=null, extra=null) {
+  let data = {
+    test: test,
+    subtest: subtest,
+    status: status,
+  };
+
+  if (expected != status && status != "SKIP") {
+    data.expected = expected;
+  }
+  if (message !== null) {
+    data.message = message;
+  }
+  if (stack !== null) {
+    data.stack = stack;
+  }
+  if (extra !== null) {
+    data.extra = extra;
+  }
+
+  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};
+
+  if (expected != status && status != "SKIP") {
+    data.expected = expected;
+  }
+  if (message !== null) {
+    data.message = message;
+  }
+  if (stack !== null) {
+    data.stack = stack;
+  }
+  if (extra !== null) {
+    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};
+  if (runinfo !== null) {
+    data.runinfo = runinfo;
+  }
+
+  this._logData("suite_start", data);
+};
+
+StructuredLogger.prototype.suiteEnd = function () {
+  this._logData("suite_end");
+};
+
+/**
+ * Unstructured logging functions
+ */
+StructuredLogger.prototype.log = function (level, message, extra=null) {
+  let data = {
+    level: level,
+    message: message,
+  };
+
+  if (extra !== null) {
+    data.extra = extra;
+  }
+
+  this._logData("log", data);
+}
+
+StructuredLogger.prototype.debug = function (message, extra=null) {
+  this.log("DEBUG", message, extra);
+}
+
+StructuredLogger.prototype.info = function (message, extra=null) {
+  this.log("INFO", message, extra);
+}
+
+StructuredLogger.prototype.warning = function (message, extra=null) {
+  this.log("WARNING", message, extra);
+}
+
+StructuredLogger.prototype.error = function (message, extra=null) {
+  this.log("ERROR", message, extra);
+}
+
+StructuredLogger.prototype.critical = function (message, extra=null) {
+  this.log("CRITICAL", message, extra);
+}
+
+StructuredLogger.prototype._logData = function (action, data={}) {
+  let allData = {
+    action: action,
+    time: Date.now(),
+    thread: null,
+    pid: null,
+    source: this.name
+  };
+
+  for (let field in data) {
+    allData[field] = data[field];
+  }
+
+  for (let fun of this._mutatorFuns) {
+    fun(allData);
+  }
+
+  this._dumpMessage(allData);
+};
+
+StructuredLogger.prototype._dumpMessage = function (message) {
+  this._dumpFun(JSON.stringify(message));
+}
--- a/testing/modules/moz.build
+++ b/testing/modules/moz.build
@@ -6,9 +6,10 @@
 
 XPCSHELL_TESTS_MANIFESTS += ['tests/xpcshell/xpcshell.ini']
 BROWSER_CHROME_MANIFESTS += ['tests/browser/browser.ini']
 
 TESTING_JS_MODULES += [
     'AppData.jsm',
     'AppInfo.jsm',
     'Assert.jsm',
+    'StructuredLog.jsm',
 ]
new file mode 100644
--- /dev/null
+++ b/testing/modules/tests/xpcshell/test_structuredlog.js
@@ -0,0 +1,161 @@
+/* Any copyright is dedicated to the Public Domain.
+   http://creativecommons.org/publicdomain/zero/1.0/ */
+
+function run_test () {
+  Components.utils.import("resource://testing-common/StructuredLog.jsm");
+
+  let testBuffer = [];
+
+  let appendBuffer = function (msg) {
+    testBuffer.push(msg);
+  }
+
+  let assertLastMsg = function (refData) {
+    // Check all fields in refData agree with those in the
+    // last message logged, and pop that message.
+    let lastMsg = JSON.parse(testBuffer.pop());
+    for (let field in refData) {
+      deepEqual(lastMsg[field], refData[field]);
+    }
+    // The logger should always set the source to the logger name.
+    equal(lastMsg.source, "test_log");
+    // The source_file field is always set by the mutator function.
+    equal(lastMsg.source_file, "test_structuredlog.js");
+  }
+
+  let addFileName = function (data) {
+    data.source_file = "test_structuredlog.js";
+  }
+
+  let logger = new StructuredLogger("test_log", appendBuffer, [addFileName]);
+
+  // Test unstructured logging
+  logger.info("Test message");
+  assertLastMsg({
+    action: "log",
+    message: "Test message",
+    level: "INFO",
+  });
+
+  logger.info("Test message",
+              extra={foo: "bar"});
+  assertLastMsg({
+    action: "log",
+    message: "Test message",
+    level: "INFO",
+    extra: {foo: "bar"},
+  });
+
+  // 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",
+    status: "OK"
+  });
+
+  // A failed test populates the "expected" field.
+  logger.testStart("aTest");
+  logger.testEnd("aTest", "FAIL", "PASS");
+  assertLastMsg({
+    action: "test_end",
+    test: "aTest",
+    status: "FAIL",
+    expected: "PASS"
+  });
+
+  // A failed test populates the "expected" field.
+  logger.testStart("aTest");
+  logger.testEnd("aTest", "FAIL", "PASS", null, "Many\nlines\nof\nstack\n");
+  assertLastMsg({
+    action: "test_end",
+    test: "aTest",
+    status: "FAIL",
+    expected: "PASS",
+    stack: "Many\nlines\nof\nstack\n"
+  });
+
+  // Skipped tests don't log failures
+  logger.testStart("aTest");
+  logger.testEnd("aTest", "SKIP", "PASS");
+  ok(!JSON.parse(testBuffer[testBuffer.length - 1]).hasOwnProperty("expected"));
+  assertLastMsg({
+    action: "test_end",
+    test: "aTest",
+    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({
+    action: "test_status",
+    test: "aTest",
+    subtest: "foo",
+    status: "PASS",
+    message: "Passed test"
+  });
+
+  logger.testStatus("aTest", "bar", "FAIL");
+  assertLastMsg({
+    action: "test_status",
+    test: "aTest",
+    subtest: "bar",
+    status: "FAIL",
+    expected: "PASS"
+  });
+
+  logger.testStatus("aTest", "bar", "FAIL", "PASS", null,
+                    "Many\nlines\nof\nstack\n");
+  assertLastMsg({
+    action: "test_status",
+    test: "aTest",
+    subtest: "bar",
+    status: "FAIL",
+    expected: "PASS",
+    stack: "Many\nlines\nof\nstack\n"
+  });
+
+  // Skipped tests don't log failures
+  logger.testStatus("aTest", "baz", "SKIP");
+  ok(!JSON.parse(testBuffer[testBuffer.length - 1]).hasOwnProperty("expected"));
+  assertLastMsg({
+    action: "test_status",
+    test: "aTest",
+    subtest: "baz",
+    status: "SKIP"
+  });
+
+  // Suite start and end messages.
+  logger.suiteStart(["aTest"]);
+  assertLastMsg({
+    action: "suite_start",
+    tests: ["aTest"],
+  });
+
+  logger.suiteEnd();
+  assertLastMsg({
+    action: "suite_end",
+  });
+}
--- a/testing/modules/tests/xpcshell/xpcshell.ini
+++ b/testing/modules/tests/xpcshell/xpcshell.ini
@@ -1,5 +1,6 @@
 [DEFAULT]
 head =
 tail =
 
 [test_assert.js]
+[test_structuredlog.js]