Bug 1731553 - [webdriver-bidi] Add support for "stackTrace" to "log.entryAdded". r=webdriver-reviewers,jdescottes

Differential Revision: https://phabricator.services.mozilla.com/D133088
2021-12-09 20:24:09 +00:00 · 2021-12-09 20:24:09 +00:00 · e9a3e7e89b
--- a/remote/shared/listeners/ConsoleAPIListener.jsm
+++ b/remote/shared/listeners/ConsoleAPIListener.jsm
@ -26,7 +26,7 @@ XPCOMUtils.defineLazyModuleGetters(this, {
 * listener.startListening();
 *
 * const onConsoleAPIMessage = (eventName, data = {}) => {
- *   const { arguments: msgArguments, level, rawMessage, timeStamp } = data;
+ *   const { arguments: msgArguments, level, stacktrace, timeStamp } = data;
 *   ...
 * };
 * ```
@ -34,8 +34,10 @@ XPCOMUtils.defineLazyModuleGetters(this, {
 * @emits message
 *    The ConsoleAPIListener emits "message" events, with the following object as
 *    payload:
- *      - `message` property pointing to the wrappedJSObject of the raw message
- *      - `rawMessage` property pointing to the raw message
+ *      - {Array<Object>} arguments - Arguments as passed-in when the method was called.
+ *      - {String} level - Importance, one of `info`, `warning`, `error`, `debug`, `trace`.
+ *      - {Array<Object>} stacktrace - List of stack frames, starting from most recent.
+ *      - {Number} timeStamp - Timestamp when the method was called.
 */
 class ConsoleAPIListener {
  #emittedMessages;
@ -121,7 +123,7 @@ class ConsoleAPIListener {
    this.emit("message", {
      arguments: messageObject.arguments,
      level: messageObject.level,
-      rawMessage: message,
+      stacktrace: messageObject.stacktrace,
      timeStamp: messageObject.timeStamp,
    });
  };
--- a/remote/shared/listeners/ConsoleListener.jsm
+++ b/remote/shared/listeners/ConsoleListener.jsm
@ -14,6 +14,7 @@ XPCOMUtils.defineLazyModuleGetters(this, {
  EventEmitter: "resource://gre/modules/EventEmitter.jsm",
  Services: "resource://gre/modules/Services.jsm",

+  getFramesFromStack: "chrome://remote/content/shared/Stack.jsm",
  Log: "chrome://remote/content/shared/Log.jsm",
 });

@ -28,7 +29,7 @@ XPCOMUtils.defineLazyGetter(this, "logger", () => Log.get());
 * Example:
 * ```
 * const onJavascriptError = (eventName, data = {}) => {
- *   const { level, message, timestamp } = data;
+ *   const { level, message, stacktrace, timestamp } = data;
 *   ...
 * };
 *
@ -38,6 +39,16 @@ XPCOMUtils.defineLazyGetter(this, "logger", () => Log.get());
 * ...
 * listener.stopListening();
 * ```
+ *
+ * @emits message
+ *    The ConsoleListener emits "error", "warning" and "info" events, with the
+ *    following object as payload:
+ *      - {String} level - Importance, one of `info`, `warning`, `error`,
+ *        `debug`, `trace`.
+ *      - {String} message - Actual message from the console entry.
+ *      - {Array<StackFrame>} stacktrace - List of stack frames,
+ *        starting from most recent.
+ *      - {Number} timeStamp - Timestamp when the method was called.
 */
 class ConsoleListener {
  #emittedMessages;
@ -139,7 +150,7 @@ class ConsoleListener {
    this.emit(level, {
      level,
      message: message.errorMessage,
-      rawMessage: message,
+      stacktrace: getFramesFromStack(message.stack),
      timeStamp: message.timeStamp,
    });
  };
--- a/remote/shared/listeners/test/browser/browser_ConsoleAPIListener.js
+++ b/remote/shared/listeners/test/browser/browser_ConsoleAPIListener.js
@ -11,6 +11,7 @@ const TESTS = [
  { method: "info", args: ["info1"] },
  { method: "debug", args: ["debug1"] },
  { method: "trace", args: ["trace1"] },
+  { method: "assert", args: [false, "assert1"] },
 ];

 const TEST_PAGE = "https://example.com/document-builder.sjs?html=tab";
@ -25,30 +26,80 @@ add_task(async function test_method_and_arguments() {

    const listenerId = await listenToConsoleAPIMessage();
    await useConsoleInContent(method, args);
-    const consoleMessage = await getConsoleAPIMessage(listenerId);
-    is(consoleMessage.level, method, "Message event has the expected level");
-    ok(
-      Number.isInteger(consoleMessage.timeStamp),
-      "Message event has a valid timestamp"
-    );
+    const {
+      arguments: msgArguments,
+      level,
+      timeStamp,
+      stacktrace,
+    } = await getConsoleAPIMessage(listenerId);
+
+    if (method == "assert") {
+      // console.assert() consumes first argument.
+      args.shift();
+    }

    is(
-      consoleMessage.arguments.length,
+      msgArguments.length,
      args.length,
      "Message event has the expected number of arguments"
    );
    for (let i = 0; i < args.length; i++) {
      Assert.deepEqual(
-        consoleMessage.arguments[i],
+        msgArguments[i],
        args[i],
        `Message event has the expected argument at index ${i}`
      );
    }
+    is(level, method, "Message event has the expected level");
+    ok(Number.isInteger(timeStamp), "Message event has a valid timestamp");
+
+    if (["assert", "error", "warn", "trace"].includes(method)) {
+      // Check stacktrace if method is allowed to contain one.
+      if (method === "warn") {
+        todo(
+          Array.isArray(stacktrace),
+          "stacktrace is of expected type Array (Bug 1744705)"
+        );
+      } else {
+        ok(Array.isArray(stacktrace), "stacktrace is of expected type Array");
+        Assert.greaterOrEqual(
+          stacktrace.length,
+          1,
+          "stack trace contains at least one frame"
+        );
+      }
+    } else {
+      is(typeof stacktrace, "undefined", "stack trace is is not present");
+    }

    gBrowser.removeTab(gBrowser.selectedTab);
  }
 });

+add_task(async function test_stacktrace() {
+  const script = `
+    function foo() { console.error("cheese"); }
+    function bar() { foo(); }
+    bar();
+  `;
+
+  const listenerId = await listenToConsoleAPIMessage();
+  await createScriptNode(script);
+  const { stacktrace } = await getConsoleAPIMessage(listenerId);
+
+  ok(Array.isArray(stacktrace), "stacktrace is of expected type Array");
+
+  // First 3 frames are from the test script.
+  Assert.greaterOrEqual(
+    stacktrace.length,
+    3,
+    "stack trace contains at least 3 frames"
+  );
+  checkStackFrame(stacktrace[0], "about:blank", "foo", 2, 30);
+  checkStackFrame(stacktrace[1], "about:blank", "bar", 3, 22);
+  checkStackFrame(stacktrace[2], "about:blank", "", 4, 5);
+});
+
 function useConsoleInContent(method, args) {
  info(`Call console API: console.${method}("${args.join('", "')}");`);
  return SpecialPowers.spawn(
@ -85,14 +136,27 @@ function getConsoleAPIMessage(listenerId) {
    async _listenerId => {
      const { consoleAPIListener, onMessage } = content[_listenerId];
      const message = await onMessage;
+
      consoleAPIListener.destroy();
-      // Note: we cannot return message directly here as it contains a
-      // `rawMessage` object which cannot be serialized by SpecialPowers.
-      return {
-        arguments: message.arguments,
-        level: message.level,
-        timeStamp: message.timeStamp,
-      };
+
+      return message;
    }
  );
 }
+
+function checkStackFrame(
+  frame,
+  filename,
+  functionName,
+  lineNumber,
+  columnNumber
+) {
+  is(frame.filename, filename, "Received expected filename for frame");
+  is(
+    frame.functionName,
+    functionName,
+    "Received expected function name for frame"
+  );
+  is(frame.lineNumber, lineNumber, "Received expected line for frame");
+  is(frame.columnNumber, columnNumber, "Received expected column for frame");
+}
--- a/remote/shared/listeners/test/browser/browser_ConsoleListener.js
+++ b/remote/shared/listeners/test/browser/browser_ConsoleListener.js
@ -2,95 +2,147 @@
 * 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/. */

+add_task(async function test_message_properties() {
+  const listenerId = await listenToConsoleMessage("error");
+  await logConsoleMessage({ message: "foo" });
+  const { level, message, timeStamp, stack } = await getConsoleMessage(
+    listenerId
+  );
+
+  is(level, "error", "Received expected log level");
+  is(message, "foo", "Received expected log message");
+  // Services.console.logMessage() doesn't include a stack.
+  is(stack, undefined, "No stack present");
+  is(typeof timeStamp, "number", "timestamp is of expected type number");
+
+  // Clear the console to avoid side effects with other tests in this file.
+  await clearConsole();
+});
+
 add_task(async function test_level() {
  for (const level of ["error", "info", "warning"]) {
-    console.info(`Testing level ${level}`);
+    const listenerId = await listenToConsoleMessage(level);
+    await logConsoleMessage({ message: "foo", level });
+    const message = await getConsoleMessage(listenerId);

-    const message = await logMessage({ level, message: "foo" });
    is(message.level, level, "Received expected log level");
-    is(message.message, "foo", "Received expected log message");
  }

-  // Clear the console to avoid side effects since there are several tasks in
-  // this file.
+  // Clear the console to avoid side effects with other tests in this file.
  await clearConsole();
 });

-add_task(async function test_message() {
-  const message = await logMessage({ message: "bar" });
-  is(message.message, "bar", "Received expected log message");
+add_task(async function test_stacktrace() {
+  const script = `
+    function foo() { throw new Error("cheese"); }
+    function bar() { foo(); }
+    bar();
+  `;

-  // Clear the console to avoid side effects since there are several tasks in
-  // this file.
+  const listenerId = await listenToConsoleMessage("error");
+  await createScriptNode(script);
+  const { message, level, stacktrace } = await getConsoleMessage(listenerId);
+  is(level, "error", "Received expected log level");
+  is(message, "Error: cheese", "Received expected log message");
+  ok(Array.isArray(stacktrace), "frames is of expected type Array");
+  Assert.greaterOrEqual(stacktrace.length, 4, "Got at least 4 stack frames");
+
+  // First 3 stack frames are from the injected script and one more frame comes
+  // from head.js (chrome scope) where we inject the script.
+  checkStackFrame(stacktrace[0], "about:blank", "foo", 2, 28);
+  checkStackFrame(stacktrace[1], "about:blank", "bar", 3, 22);
+  checkStackFrame(stacktrace[2], "about:blank", "", 4, 5);
+  checkStackFrame(
+    stacktrace[3],
+    "chrome://mochitests/content/browser/remote/shared/listeners/test/browser/head.js",
+    "",
+    33,
+    27
+  );
+
+  // Clear the console to avoid side effects with other tests in this file.
  await clearConsole();
 });

-async function logMessage(options = {}) {
-  const { inContent = true } = options;
+function logConsoleMessage(options = {}) {
+  info(`Log console message ${options.message}`);
+  return SpecialPowers.spawn(gBrowser.selectedBrowser, [options], _options => {
+    const { level = "error" } = _options;

-  const addScriptErrorInternal = async ({ options }) => {
-    const {
-      level = "error",
-      innerWindowId = content.windowGlobalChild.innerWindowId,
-    } = options;
+    const levelToFlags = {
+      error: Ci.nsIScriptError.errorFlag,
+      info: Ci.nsIScriptError.infoFlag,
+      warning: Ci.nsIScriptError.warningFlag,
+    };

-    const { ConsoleListener } = ChromeUtils.import(
-      "chrome://remote/content/shared/listeners/ConsoleListener.jsm"
+    const scriptError = Cc["@mozilla.org/scripterror;1"].createInstance(
+      Ci.nsIScriptError
+    );
+    scriptError.initWithWindowID(
+      _options.message,
+      _options.sourceName || "sourceName",
+      null,
+      _options.lineNumber || 0,
+      _options.columnNumber || 0,
+      levelToFlags[level],
+      _options.category || "javascript",
+      content.windowGlobalChild.innerWindowId
    );

-    const consoleListener = new ConsoleListener(innerWindowId);
-    let listener;
+    Services.console.logMessage(scriptError);
+  });
+}

-    return new Promise(resolve => {
-      listener = (eventName, data) => {
-        is(eventName, level, "Expected event has been fired");
-
-        const { level: currentLevel, message, timeStamp } = data;
-        is(typeof currentLevel, "string", "level is of type string");
-        is(typeof message, "string", "message is of type string");
-        is(typeof timeStamp, "number", "timeStamp is of type number");
-
-        resolve(data);
-      };
-
-      consoleListener.on(level, listener);
+function listenToConsoleMessage(level) {
+  info("Listen to a console message in content");
+  return SpecialPowers.spawn(
+    gBrowser.selectedBrowser,
+    [level],
+    async _level => {
+      const innerWindowId = content.windowGlobalChild.innerWindowId;
+      const { ConsoleListener } = ChromeUtils.import(
+        "chrome://remote/content/shared/listeners/ConsoleListener.jsm"
+      );
+      const consoleListener = new ConsoleListener(innerWindowId);
+      const onMessage = consoleListener.once(_level);
      consoleListener.startListening();

-      const levelToFlags = {
-        error: Ci.nsIScriptError.errorFlag,
-        info: Ci.nsIScriptError.infoFlag,
-        warning: Ci.nsIScriptError.warningFlag,
-      };
-
-      const scriptError = Cc["@mozilla.org/scripterror;1"].createInstance(
-        Ci.nsIScriptError
-      );
-      scriptError.initWithWindowID(
-        options.message,
-        options.sourceName || "sourceName",
-        null,
-        options.lineNumber || 0,
-        options.columnNumber || 0,
-        levelToFlags[level],
-        options.category || "javascript",
-        innerWindowId
-      );
-
-      Services.console.logMessage(scriptError);
-    }).finally(() => {
-      consoleListener.off(level, listener);
-      consoleListener.destroy();
-    });
-  };
-
-  if (inContent) {
-    return ContentTask.spawn(
-      gBrowser.selectedBrowser,
-      { options },
-      addScriptErrorInternal
-    );
-  }
-
-  options.innerWindowId = window.windowGlobalChild.innerWindowId;
-  return addScriptErrorInternal({ options });
+      const listenerId = Math.random();
+      content[listenerId] = { consoleListener, onMessage };
+      return listenerId;
+    }
+  );
+}
+
+function getConsoleMessage(listenerId) {
+  info("Retrieve the message event captured for listener: " + listenerId);
+  return SpecialPowers.spawn(
+    gBrowser.selectedBrowser,
+    [listenerId],
+    async _listenerId => {
+      const { consoleListener, onMessage } = content[_listenerId];
+      const message = await onMessage;
+
+      consoleListener.destroy();
+
+      return message;
+    }
+  );
+}
+
+function checkStackFrame(
+  frame,
+  filename,
+  functionName,
+  lineNumber,
+  columnNumber
+) {
+  is(frame.filename, filename, "Received expected filename for frame");
+  is(
+    frame.functionName,
+    functionName,
+    "Received expected function name for frame"
+  );
+  is(frame.lineNumber, lineNumber, "Received expected line for frame");
+  is(frame.columnNumber, columnNumber, "Received expected column for frame");
 }
--- a/remote/shared/listeners/test/browser/browser_ConsoleListener_cached_messages.js
+++ b/remote/shared/listeners/test/browser/browser_ConsoleListener_cached_messages.js
@ -82,23 +82,3 @@ add_task(async function test_cached_javascript_errors() {

  gBrowser.removeTab(gBrowser.selectedTab);
 });
-
-/**
- * Execute the provided script content by generating a dynamic script tag and
- * inserting it in the page for the current selected browser.
- *
- * @param {string} script
- *     The script to execute.
- * @return {Promise}
- *     A promise that resolves when the script node was added and removed from
- *     the content page.
- */
-function createScriptNode(script) {
-  return SpecialPowers.spawn(gBrowser.selectedBrowser, [script], function(
-    _script
-  ) {
-    var script = content.document.createElement("script");
-    script.append(content.document.createTextNode(_script));
-    content.document.body.append(script);
-  });
-}
--- a/remote/shared/listeners/test/browser/head.js
+++ b/remote/shared/listeners/test/browser/head.js
@ -13,6 +13,26 @@ async function clearConsole() {
  Services.console.reset();
 }

+/**
+ * Execute the provided script content by generating a dynamic script tag and
+ * inserting it in the page for the current selected browser.
+ *
+ * @param {string} script
+ *     The script to execute.
+ * @return {Promise}
+ *     A promise that resolves when the script node was added and removed from
+ *     the content page.
+ */
+function createScriptNode(script) {
+  return SpecialPowers.spawn(gBrowser.selectedBrowser, [script], function(
+    _script
+  ) {
+    var script = content.document.createElement("script");
+    script.append(content.document.createTextNode(_script));
+    content.document.body.append(script);
+  });
+}
+
 registerCleanupFunction(async () => {
  await clearConsole();
 });
--- a/remote/webdriver-bidi/modules/windowglobal/log.jsm
+++ b/remote/webdriver-bidi/modules/windowglobal/log.jsm
@ -15,6 +15,7 @@ XPCOMUtils.defineLazyModuleGetters(this, {
    "chrome://remote/content/shared/listeners/ConsoleAPIListener.jsm",
  ConsoleListener:
    "chrome://remote/content/shared/listeners/ConsoleListener.jsm",
+  isChromeFrame: "chrome://remote/content/shared/Stack.jsm",
  Module: "chrome://remote/content/shared/messagehandler/Module.jsm",
  serialize: "chrome://remote/content/webdriver-bidi/RemoteValue.jsm",
 });
@ -78,10 +79,47 @@ class Log extends Module {
    }
  }

+  /**
+   * Map the internal stacktrace representation to a WebDriver BiDi
+   * compatible one.
+   *
+   * Currently chrome frames will be filtered out until chrome scope
+   * is supported (bug 1722679).
+   *
+   * @param {Array<StackFrame>=} stackTrace
+   *     Stack frames to process.
+   *
+   * @returns {Object=} Object, containing the list of frames as `callFrames`.
+   */
+  #buildStackTrace(stackTrace) {
+    if (stackTrace == undefined) {
+      return undefined;
+    }
+
+    const callFrames = stackTrace
+      .filter(frame => !isChromeFrame(frame))
+      .map(frame => {
+        return {
+          columnNumber: frame.columnNumber,
+          functionName: frame.functionName,
+          // Match WebDriver BiDi and convert Firefox's one-based line number.
+          lineNumber: frame.lineNumber - 1,
+          url: frame.filename,
+        };
+      });
+
+    return { callFrames };
+  }
+
  #onConsoleAPIMessage = (eventName, data = {}) => {
-    // `arguments` cannot be used as variable name in functions
-    // `level` corresponds to the console method used
-    const { arguments: messageArguments, level: method, timeStamp } = data;
+    const {
+      // `arguments` cannot be used as variable name in functions
+      arguments: messageArguments,
+      // `level` corresponds to the console method used
+      level: method,
+      stacktrace,
+      timeStamp,
+    } = data;

    // Step numbers below refer to the specifications at
    //   https://w3c.github.io/webdriver-bidi/#event-log-entryAdded
@ -111,19 +149,24 @@ class Log extends Module {
      serializedArgs.push(serialize(arg /*, null, true, new Set() */));
    }

-    // 8. TODO: set realm to the current realm id.
+    // 8. Bug 1742589: set realm to the current realm id.

-    // 9. TODO: set stack to the current stack trace.
+    // 9. Set stack trace only for certain methods.
+    let stackTrace;
+    if (["assert", "error", "trace", "warn"].includes(method)) {
+      stackTrace = this.#buildStackTrace(stacktrace);
+    }

    // 10. Build the ConsoleLogEntry
    const entry = {
      type: "console",
-      level: logEntrylevel,
-      text,
-      timestamp,
      method,
      realm: null,
      args: serializedArgs,
+      level: logEntrylevel,
+      text,
+      timestamp,
+      stackTrace,
    };

    // TODO: steps 11. to 15. Those steps relate to:
@ -138,15 +181,15 @@ class Log extends Module {
  };

  #onJavaScriptError = (eventName, data = {}) => {
-    const { level, message, timeStamp } = data;
+    const { level, message, stacktrace, timeStamp } = data;

+    // Build the JavascriptLogEntry
    const entry = {
      type: "javascript",
      level,
      text: message,
      timestamp: timeStamp || Date.now(),
-      // TODO: Bug 1731553
-      stackTrace: undefined,
+      stackTrace: this.#buildStackTrace(stacktrace),
    };

    this.messageHandler.emitMessageHandlerEvent("log.entryAdded", entry);