testing/modules/StructuredLog.jsm

   1 /* This Source Code Form is subject to the terms of the Mozilla Public
   2  * License, v. 2.0. If a copy of the MPL was not distributed with this
   3  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
   4
   5 "use strict";
   6
   7 var EXPORTED_SYMBOLS = ["StructuredLogger", "StructuredFormatter"];
   8
   9 /**
  10  * TestLogger: Logger class generating messages compliant with the
  11  * structured logging protocol for tests exposed by mozlog
  12  *
  13  * @param name
  14  *        The name of the logger to instantiate.
  15  * @param dumpFun
  16  *        An underlying function to be used to log raw messages. This function
  17  *        will receive the complete serialized json string to log.
  18  * @param mutators
  19  *        An array of functions used to add global context to log messages.
  20  *        These will each be called with the complete object to log as an
  21  *        argument.
  22  */
  23 var StructuredLogger = function(name, dumpFun = dump, mutators = []) {
  24   this.name = name;
  25   this._dumpFun = dumpFun;
  26   this._mutatorFuns = mutators;
  27 };
  28
  29 /**
  30  * Log functions producing messages in the format specified by mozlog
  31  */
  32 StructuredLogger.prototype = {
  33   testStart(test) {
  34     var data = { test: this._testId(test) };
  35     this._logData("test_start", data);
  36   },
  37
  38   testStatus(
  39     test,
  40     subtest,
  41     status,
  42     expected = "PASS",
  43     message = null,
  44     stack = null,
  45     extra = null
  46   ) {
  47     if (subtest === null || subtest === undefined) {
  48       // Fix for assertions that don't pass in a name
  49       subtest = "undefined assertion name";
  50     }
  51
  52     var data = {
  53       test: this._testId(test),
  54       subtest,
  55       status,
  56     };
  57
  58     if (expected != status && status != "SKIP") {
  59       data.expected = expected;
  60     }
  61     if (message !== null) {
  62       data.message = String(message);
  63     }
  64     if (stack !== null) {
  65       data.stack = stack;
  66     }
  67     if (extra !== null) {
  68       data.extra = extra;
  69     }
  70
  71     this._logData("test_status", data);
  72   },
  73
  74   testEnd(
  75     test,
  76     status,
  77     expected = "OK",
  78     message = null,
  79     stack = null,
  80     extra = null
  81   ) {
  82     var data = { test: this._testId(test), status };
  83
  84     if (expected != status && status != "SKIP") {
  85       data.expected = expected;
  86     }
  87     if (message !== null) {
  88       data.message = String(message);
  89     }
  90     if (stack !== null) {
  91       data.stack = stack;
  92     }
  93     if (extra !== null) {
  94       data.extra = extra;
  95     }
  96
  97     this._logData("test_end", data);
  98   },
  99
 100   assertionCount(test, count, minExpected = 0, maxExpected = 0) {
 101     var data = {
 102       test: this._testId(test),
 103       min_expected: minExpected,
 104       max_expected: maxExpected,
 105       count,
 106     };
 107
 108     this._logData("assertion_count", data);
 109   },
 110
 111   suiteStart(
 112     ids,
 113     name = null,
 114     runinfo = null,
 115     versioninfo = null,
 116     deviceinfo = null,
 117     extra = null
 118   ) {
 119     Object.keys(ids).map(function(manifest) {
 120       ids[manifest] = ids[manifest].map(x => this._testId(x));
 121     }, this);
 122     var data = { tests: ids };
 123
 124     if (name !== null) {
 125       data.name = name;
 126     }
 127
 128     if (runinfo !== null) {
 129       data.runinfo = runinfo;
 130     }
 131
 132     if (versioninfo !== null) {
 133       data.versioninfo = versioninfo;
 134     }
 135
 136     if (deviceinfo !== null) {
 137       data.deviceinfo = deviceinfo;
 138     }
 139
 140     if (extra !== null) {
 141       data.extra = extra;
 142     }
 143
 144     this._logData("suite_start", data);
 145   },
 146
 147   suiteEnd(extra = null) {
 148     var data = {};
 149
 150     if (extra !== null) {
 151       data.extra = extra;
 152     }
 153
 154     this._logData("suite_end", data);
 155   },
 156
 157   /**
 158    * Unstructured logging functions. The "extra" parameter can always by used to
 159    * log suite specific data. If a "stack" field is provided it is logged at the
 160    * top level of the data object for the benefit of mozlog's formatters.
 161    */
 162   log(level, message, extra = null) {
 163     var data = {
 164       level,
 165       message: String(message),
 166     };
 167
 168     if (extra !== null) {
 169       data.extra = extra;
 170       if ("stack" in extra) {
 171         data.stack = extra.stack;
 172       }
 173     }
 174
 175     this._logData("log", data);
 176   },
 177
 178   debug(message, extra = null) {
 179     this.log("DEBUG", message, extra);
 180   },
 181
 182   info(message, extra = null) {
 183     this.log("INFO", message, extra);
 184   },
 185
 186   warning(message, extra = null) {
 187     this.log("WARNING", message, extra);
 188   },
 189
 190   error(message, extra = null) {
 191     this.log("ERROR", message, extra);
 192   },
 193
 194   critical(message, extra = null) {
 195     this.log("CRITICAL", message, extra);
 196   },
 197
 198   processOutput(thread, message) {
 199     this._logData("process_output", {
 200       message,
 201       thread,
 202     });
 203   },
 204
 205   _logData(action, data = {}) {
 206     var allData = {
 207       action,
 208       time: Date.now(),
 209       thread: null,
 210       pid: null,
 211       source: this.name,
 212     };
 213
 214     for (var field in data) {
 215       allData[field] = data[field];
 216     }
 217
 218     for (var fun of this._mutatorFuns) {
 219       fun(allData);
 220     }
 221
 222     this._dumpFun(allData);
 223   },
 224
 225   _testId(test) {
 226     if (Array.isArray(test)) {
 227       return test.join(" ");
 228     }
 229     return test;
 230   },
 231 };
 232
 233 /**
 234  * StructuredFormatter: Formatter class turning structured messages
 235  * into human-readable messages.
 236  */
 237 var StructuredFormatter = function() {
 238   this.testStartTimes = {};
 239 };
 240
 241 StructuredFormatter.prototype = {
 242   log(message) {
 243     return message.message;
 244   },
 245
 246   suite_start(message) {
 247     this.suiteStartTime = message.time;
 248     return "SUITE-START | Running " + message.tests.length + " tests";
 249   },
 250
 251   test_start(message) {
 252     this.testStartTimes[message.test] = new Date().getTime();
 253     return "TEST-START | " + message.test;
 254   },
 255
 256   test_status(message) {
 257     var statusInfo =
 258       message.test +
 259       " | " +
 260       message.subtest +
 261       (message.message ? " | " + message.message : "");
 262     if (message.expected) {
 263       return (
 264         "TEST-UNEXPECTED-" +
 265         message.status +
 266         " | " +
 267         statusInfo +
 268         " - expected: " +
 269         message.expected
 270       );
 271     }
 272     return "TEST-" + message.status + " | " + statusInfo;
 273   },
 274
 275   test_end(message) {
 276     var startTime = this.testStartTimes[message.test];
 277     delete this.testStartTimes[message.test];
 278     var statusInfo =
 279       message.test + (message.message ? " | " + String(message.message) : "");
 280     var result;
 281     if (message.expected) {
 282       result =
 283         "TEST-UNEXPECTED-" +
 284         message.status +
 285         " | " +
 286         statusInfo +
 287         " - expected: " +
 288         message.expected;
 289     } else {
 290       return "TEST-" + message.status + " | " + statusInfo;
 291     }
 292     result = result + " | took " + message.time - startTime + "ms";
 293     return result;
 294   },
 295
 296   suite_end(message) {
 297     return "SUITE-END | took " + message.time - this.suiteStartTime + "ms";
 298   },
 299 };