testing/modules/StructuredLog.sys.mjs

   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 /**
   6  * TestLogger: Logger class generating messages compliant with the
   7  * structured logging protocol for tests exposed by mozlog
   8  *
   9  * @param {string} name
  10  *        The name of the logger to instantiate.
  11  * @param {function} [dumpFun]
  12  *        An underlying function to be used to log raw messages. This function
  13  *        will receive the complete serialized json string to log.
  14  * @param {object} [scope]
  15  *        The scope that the dumpFun is loaded in, so that messages are cloned
  16  *        into that scope before passing them.
  17  */
  18 export class StructuredLogger {
  19   name = null;
  20   #dumpFun = null;
  21   #dumpScope = null;
  22
  23   constructor(name, dumpFun = dump, scope = null) {
  24     this.name = name;
  25     this.#dumpFun = dumpFun;
  26     this.#dumpScope = scope;
  27   }
  28
  29   testStart(test) {
  30     var data = { test: this.#testId(test) };
  31     this.logData("test_start", data);
  32   }
  33
  34   testStatus(
  35     test,
  36     subtest,
  37     status,
  38     expected = "PASS",
  39     message = null,
  40     stack = null,
  41     extra = null
  42   ) {
  43     if (subtest === null || subtest === undefined) {
  44       // Fix for assertions that don't pass in a name
  45       subtest = "undefined assertion name";
  46     }
  47
  48     var data = {
  49       test: this.#testId(test),
  50       subtest,
  51       status,
  52     };
  53
  54     // handle case: known fail
  55     if (expected === status && status != "SKIP") {
  56       data.status = "PASS";
  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     // handle case: known fail
  85     if (expected === status && status != "SKIP") {
  86       data.status = "OK";
  87     }
  88     if (expected != status && status != "SKIP") {
  89       data.expected = expected;
  90     }
  91     if (message !== null) {
  92       data.message = String(message);
  93     }
  94     if (stack !== null) {
  95       data.stack = stack;
  96     }
  97     if (extra !== null) {
  98       data.extra = extra;
  99     }
 100
 101     this.logData("test_end", data);
 102   }
 103
 104   assertionCount(test, count, minExpected = 0, maxExpected = 0) {
 105     var data = {
 106       test: this.#testId(test),
 107       min_expected: minExpected,
 108       max_expected: maxExpected,
 109       count,
 110     };
 111
 112     this.logData("assertion_count", data);
 113   }
 114
 115   suiteStart(
 116     ids,
 117     name = null,
 118     runinfo = null,
 119     versioninfo = null,
 120     deviceinfo = null,
 121     extra = null
 122   ) {
 123     Object.keys(ids).map(function (manifest) {
 124       ids[manifest] = ids[manifest].map(x => this.#testId(x));
 125     }, this);
 126     var data = { tests: ids };
 127
 128     if (name !== null) {
 129       data.name = name;
 130     }
 131
 132     if (runinfo !== null) {
 133       data.runinfo = runinfo;
 134     }
 135
 136     if (versioninfo !== null) {
 137       data.versioninfo = versioninfo;
 138     }
 139
 140     if (deviceinfo !== null) {
 141       data.deviceinfo = deviceinfo;
 142     }
 143
 144     if (extra !== null) {
 145       data.extra = extra;
 146     }
 147
 148     this.logData("suite_start", data);
 149   }
 150
 151   suiteEnd(extra = null) {
 152     var data = {};
 153
 154     if (extra !== null) {
 155       data.extra = extra;
 156     }
 157
 158     this.logData("suite_end", data);
 159   }
 160
 161   /**
 162    * Unstructured logging functions. The "extra" parameter can always by used to
 163    * log suite specific data. If a "stack" field is provided it is logged at the
 164    * top level of the data object for the benefit of mozlog's formatters.
 165    */
 166   log(level, message, extra = null) {
 167     var data = {
 168       level,
 169       message: String(message),
 170     };
 171
 172     if (extra !== null) {
 173       data.extra = extra;
 174       if ("stack" in extra) {
 175         data.stack = extra.stack;
 176       }
 177     }
 178
 179     this.logData("log", data);
 180   }
 181
 182   debug(message, extra = null) {
 183     this.log("DEBUG", message, extra);
 184   }
 185
 186   info(message, extra = null) {
 187     this.log("INFO", message, extra);
 188   }
 189
 190   warning(message, extra = null) {
 191     this.log("WARNING", message, extra);
 192   }
 193
 194   error(message, extra = null) {
 195     this.log("ERROR", message, extra);
 196   }
 197
 198   critical(message, extra = null) {
 199     this.log("CRITICAL", message, extra);
 200   }
 201
 202   processOutput(thread, message) {
 203     this.logData("process_output", {
 204       message,
 205       thread,
 206     });
 207   }
 208
 209   logData(action, data = {}) {
 210     var allData = {
 211       action,
 212       time: Date.now(),
 213       thread: null,
 214       pid: null,
 215       source: this.name,
 216     };
 217
 218     for (var field in data) {
 219       allData[field] = data[field];
 220     }
 221
 222     if (this.#dumpScope) {
 223       this.#dumpFun(Cu.cloneInto(allData, this.#dumpScope));
 224     } else {
 225       this.#dumpFun(allData);
 226     }
 227   }
 228
 229   #testId(test) {
 230     if (Array.isArray(test)) {
 231       return test.join(" ");
 232     }
 233     return test;
 234   }
 235 }
 236
 237 /**
 238  * StructuredFormatter: Formatter class turning structured messages
 239  * into human-readable messages.
 240  */
 241 export class StructuredFormatter {
 242   // The time at which the whole suite of tests started.
 243   #suiteStartTime = null;
 244
 245   #testStartTimes = new Map();
 246
 247   log(message) {
 248     return message.message;
 249   }
 250
 251   suite_start(message) {
 252     this.#suiteStartTime = message.time;
 253     return "SUITE-START | Running " + message.tests.length + " tests";
 254   }
 255
 256   test_start(message) {
 257     this.#testStartTimes.set(message.test, new Date().getTime());
 258     return "TEST-START | " + message.test;
 259   }
 260
 261   test_status(message) {
 262     var statusInfo =
 263       message.test +
 264       " | " +
 265       message.subtest +
 266       (message.message ? " | " + message.message : "");
 267     if (message.expected) {
 268       return (
 269         "TEST-UNEXPECTED-" +
 270         message.status +
 271         " | " +
 272         statusInfo +
 273         " - expected: " +
 274         message.expected
 275       );
 276     }
 277     return "TEST-" + message.status + " | " + statusInfo;
 278   }
 279
 280   test_end(message) {
 281     var startTime = this.#testStartTimes.get(message.test);
 282     this.#testStartTimes.delete(message.test);
 283     var statusInfo =
 284       message.test + (message.message ? " | " + String(message.message) : "");
 285     var result;
 286     if (message.expected) {
 287       result =
 288         "TEST-UNEXPECTED-" +
 289         message.status +
 290         " | " +
 291         statusInfo +
 292         " - expected: " +
 293         message.expected;
 294     } else {
 295       return "TEST-" + message.status + " | " + statusInfo;
 296     }
 297     result = result + " | took " + message.time - startTime + "ms";
 298     return result;
 299   }
 300
 301   suite_end(message) {
 302     return "SUITE-END | took " + message.time - this.#suiteStartTime + "ms";
 303   }
 304 }