/* 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/. */ let gSchemaRegistered = false; function ensureSchemaRegistered() { if (gSchemaRegistered) { return; } gSchemaRegistered = true; /** * @backward-compat { version 149 } * * Bug 2011308: Remove the following typeof / early return check */ if (!ChromeUtils.registerMarkerSchema) { return; } ChromeUtils.registerMarkerSchema({ name: "TestStatus", tableLabel: "{marker.data.message}", display: ["marker-chart", "marker-table"], colorField: "color", data: [ { key: "message", label: "Message", format: "string", }, { key: "test", label: "Test Name", format: "string", }, { key: "subtest", label: "Subtest", format: "string", }, { key: "status", label: "Status", format: "string", }, { key: "expected", label: "Expected", format: "string", }, { key: "color", hidden: true, }, ], }); ChromeUtils.registerMarkerSchema({ name: "Test", tooltipLabel: "{marker.data.name}", tableLabel: "{marker.data.status} — {marker.data.test}", chartLabel: "{marker.data.name}", display: ["marker-chart", "marker-table"], colorField: "color", data: [ { key: "test", label: "Test Name", format: "string", }, { key: "name", label: "Short Name", format: "string", hidden: true, }, { key: "status", label: "Status", format: "string", }, { key: "expected", label: "Expected", format: "string", }, { key: "message", label: "Message", format: "string", }, { key: "color", hidden: true, }, ], }); ChromeUtils.registerMarkerSchema({ name: "Log", tableLabel: "{marker.data.message}", display: ["marker-chart", "marker-table"], colorField: "color", data: [ { key: "message", label: "Message", format: "string", }, { key: "level", label: "Level", format: "string", }, { key: "test", label: "Test Name", format: "string", }, { key: "subtest", label: "Subtest", format: "string", }, { key: "color", hidden: true, }, ], }); } /** * TestLogger: Logger class generating messages compliant with the * structured logging protocol for tests exposed by mozlog * * @param {string} name * The name of the logger to instantiate. * @param {function} [dumpFun] * An underlying function to be used to log raw messages. This function * will receive the complete serialized json string to log. * @param {object} [scope] * The scope that the dumpFun is loaded in, so that messages are cloned * into that scope before passing them. */ export class StructuredLogger { name = null; #dumpFun = null; #dumpScope = null; #testStartTimes = new Map(); // Regexes that normalize test paths, matching MessageLogger.TEST_PATH_PREFIXES static #TEST_PATH_PREFIXES = [ /^\/tests\//, /^\w+:\/\/[\w.]+(:\d+)?(\/\w+)?\/(tests?|a11y|chrome)\//, /^\w+:\/\/[\w.]+(:\d+)?(\/\w+)?\/(tests?|browser)\//, ]; constructor(name, dumpFun = dump, scope = null) { this.name = name; this.#dumpFun = dumpFun; this.#dumpScope = scope; } /** * Normalize a test path to match the relative path from the sourcedir. * Matches the behavior of MessageLogger._fix_test_name in runtests.py. */ #normalizeTestPath(testPath) { for (const pattern of StructuredLogger.#TEST_PATH_PREFIXES) { const normalized = testPath.replace(pattern, ""); if (normalized !== testPath) { return normalized; } } return testPath; } testStart(test) { var data = { test: this.#testId(test) }; this.logData("test_start", data); const testId = this.#testId(test); this.#testStartTimes.set(testId, ChromeUtils.now()); } testStatus( test, subtest, status, expected = "PASS", message = null, stack = null, extra = null ) { var data = { test: this.#testId(test), subtest, status, }; if (expected != status && status != "SKIP") { data.expected = expected; } if (message !== null) { data.message = String(message); } if (stack !== null) { data.stack = stack; } if (extra !== null) { data.extra = extra; } this.logData("test_status", data); ensureSchemaRegistered(); // Determine marker name following mochitest conventions let markerName; if (status === expected) { // Expected result if (status === "FAIL") { markerName = "TEST-KNOWN-FAIL"; } else { markerName = "TEST-" + status; } } else { // Unexpected result markerName = "TEST-UNEXPECTED-" + status; } // Prepare marker data with normalized test path const markerData = { type: "TestStatus", test: this.#normalizeTestPath(data.test), status, expected, }; if (subtest) { markerData.subtest = subtest; } if (message !== null) { markerData.message = String(message); } // Determine color if (status === "ERROR" && status !== expected) { markerData.color = "red"; } else if (status === expected) { markerData.color = "green"; } else { markerData.color = "orange"; } const options = { category: "Test" }; // Capture stack for failures and errors if (status === "FAIL" || status === "ERROR") { options.captureStack = true; } ChromeUtils.addProfilerMarker(markerName, options, markerData); } testEnd( test, status, expected = "PASS", message = null, stack = null, extra = null ) { const testId = this.#testId(test); var data = { test: testId, status }; if (expected != status && status != "SKIP") { data.expected = expected; } if (message !== null) { data.message = String(message); } if (stack !== null) { data.stack = stack; } if (extra !== null) { data.extra = extra; } this.logData("test_end", data); const startTime = this.#testStartTimes.get(testId); if (!startTime) { return; } this.#testStartTimes.delete(testId); ensureSchemaRegistered(); // Normalize test path const testPath = this.#normalizeTestPath(testId); const markerData = { type: "Test", test: testPath, name: testPath.split("/").pop(), status, }; if (data.expected) { markerData.expected = data.expected; } if (data.message) { markerData.message = data.message; } if (status) { // Determine color based on status and expectations if (status === "SKIP" || status === "TIMEOUT") { markerData.color = "yellow"; } else if (status === "CRASH" || status === "ERROR") { markerData.color = "red"; } else if (expected === status) { markerData.color = "green"; } else { markerData.color = "orange"; } } ChromeUtils.addProfilerMarker( "test", { category: "Test", startTime, }, markerData ); } assertionCount(test, count, minExpected = 0, maxExpected = 0) { var data = { test: this.#testId(test), min_expected: minExpected, max_expected: maxExpected, count, }; this.logData("assertion_count", data); } suiteStart( ids, name = null, runinfo = null, versioninfo = null, deviceinfo = null, extra = null ) { Object.keys(ids).map(function (manifest) { ids[manifest] = ids[manifest].map(x => this.#testId(x)); }, this); var data = { tests: ids }; if (name !== null) { data.name = name; } if (runinfo !== null) { data.runinfo = runinfo; } if (versioninfo !== null) { data.versioninfo = versioninfo; } if (deviceinfo !== null) { data.deviceinfo = deviceinfo; } if (extra !== null) { data.extra = extra; } this.logData("suite_start", data); } suiteEnd(extra = null) { var data = {}; if (extra !== null) { data.extra = extra; } this.logData("suite_end", data); } /** * 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. */ log(level, message, extra = null) { var data = { level, message: String(message), }; if (extra !== null) { data.extra = extra; if ("stack" in extra) { data.stack = extra.stack; } } this.logData("log", data); ensureSchemaRegistered(); // Add marker type data.type = "Log"; // Copy test/subtest from extra if present, normalizing test path if (extra) { if (extra.test) { data.test = this.#normalizeTestPath(extra.test); } if (extra.subtest) { data.subtest = extra.subtest; } } // Determine color based on log level if (level === "CRITICAL" || level === "ERROR") { data.color = "red"; } else if (level === "WARNING") { data.color = "orange"; } else if (level === "DEBUG") { data.color = "grey"; } // Remove fields we don't want in the marker delete data.extra; const options = { category: "Test" }; // Capture stack for errors and critical if (level === "CRITICAL" || level === "ERROR") { options.captureStack = true; } ChromeUtils.addProfilerMarker(level, options, data); } debug(message, extra = null) { this.log("DEBUG", message, extra); } info(message, extra = null) { this.log("INFO", message, extra); } warning(message, extra = null) { this.log("WARNING", message, extra); } error(message, extra = null) { this.log("ERROR", message, extra); } critical(message, extra = null) { this.log("CRITICAL", message, extra); } processOutput(thread, message) { this.logData("process_output", { message, thread, }); } logData(action, data = {}) { var allData = { action, time: Date.now(), thread: null, pid: null, source: this.name, }; for (var field in data) { allData[field] = data[field]; } if (this.#dumpScope) { try { allData = Cu.cloneInto(allData, this.#dumpScope); } catch (e) { try { this.error(`Failed to cloneInto: ${e}`); this.warning(`Tried to clone: ${uneval(allData)}`); } catch (e2) { console.error("Failed to handle clone error", e, e2); } } } this.#dumpFun(allData); } #testId(test) { if (Array.isArray(test)) { return test.join(" "); } return test; } } /** * StructuredFormatter: Formatter class turning structured messages * into human-readable messages. */ export class StructuredFormatter { // The time at which the whole suite of tests started. #suiteStartTime = null; #testStartTimes = new Map(); log(message) { return message.message; } suite_start(message) { this.#suiteStartTime = message.time; return "SUITE-START | Running " + message.tests.length + " tests"; } test_start(message) { this.#testStartTimes.set(message.test, new Date().getTime()); return "TEST-START | " + message.test; } test_status(message) { var statusInfo = message.test + " | " + message.subtest + (message.message ? " | " + message.message : ""); if (message.expected) { return ( "TEST-UNEXPECTED-" + message.status + " | " + statusInfo + " - expected: " + message.expected ); } return "TEST-" + message.status + " | " + statusInfo; } test_end(message) { var startTime = this.#testStartTimes.get(message.test); this.#testStartTimes.delete(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 = result + " | took " + message.time - startTime + "ms"; return result; } suite_end(message) { return "SUITE-END | took " + message.time - this.#suiteStartTime + "ms"; } }