Bug 1998953 - [remote] Improve logging when prompts are opened and closed. r=jdescottes

Differential Revision: https://phabricator.services.mozilla.com/D271801

Author: whimboo

remote/marionette/driver.sys.mjs

@@ -334,6 +334,14 @@ export function GeckoDriver(server) {
   this._actionsHelper = new ActionsHelper(this);
 }
 
+GeckoDriver.prototype._trace = function (message, browsingContext = null) {
+  if (browsingContext !== null) {
+    lazy.logger.trace(`[${browsingContext.id}] ${message}`);
+  } else {
+    lazy.logger.trace(message);
+  }
+};
+
 /**
  * The current context decides if commands are executed in chrome- or
  * content space.
@@ -410,20 +418,39 @@ GeckoDriver.prototype.QueryInterface = ChromeUtils.generateQI([
  * Callback used to observe the closing of modal dialogs
  * during the session's lifetime.
  */
-GeckoDriver.prototype.handleClosedModalDialog = function () {
+GeckoDriver.prototype.handleClosedModalDialog = function (_eventName, data) {
+  const { contentBrowser, detail } = data;
+
+  this._trace(
+    `Prompt closed (type: "${detail.promptType}", accepted: "${detail.accepted}")`,
+    contentBrowser.browsingContext
+  );
+
   this.dialog = null;
 };
 
 /**
  * Callback used to observe the creation of new modal dialogs
  * during the session's lifetime.
  */
-GeckoDriver.prototype.handleOpenModalDialog = function (eventName, data) {
-  this.dialog = data.prompt;
+GeckoDriver.prototype.handleOpenModalDialog = function (_eventName, data) {
+  const { contentBrowser, prompt } = data;
+
+  prompt.getText().then(text => {
+    // We need the text to identify a user prompt when it gets
+    // randomly opened. Because on Android the text is asynchronously
+    // retrieved lets delay the logging without making the handler async.
+    this._trace(
+      `Prompt opened (type: "${prompt.promptType}", text: "${text}")`,
+      contentBrowser.browsingContext
+    );
+  });
+
+  this.dialog = prompt;
 
   if (this.dialog.promptType === "beforeunload" && !this.currentSession?.bidi) {
     // Only implicitly accept the prompt when its not a BiDi session.
-    lazy.logger.trace(`Implicitly accepted "beforeunload" prompt`);
+    this._trace(`Implicitly accepted "beforeunload" prompt`);
     this.dialog.accept();
     return;
   }

remote/shared/listeners/PromptListener.sys.mjs

@@ -85,8 +85,6 @@ export class PromptListener {
    * Handles `DOMModalDialogClosed` events.
    */
   handleEvent(event) {
-    lazy.logger.trace(`Received event ${event.type}`);
-
     const chromeWin = event.target.opener
       ? event.target.opener.ownerGlobal
       : event.target.ownerGlobal;
@@ -136,12 +134,10 @@ export class PromptListener {
    * `domwindowopened` - when a new chrome window opened,
    * `geckoview-prompt-show` - when a modal dialog opened on Android.
    */
-  observe(subject, topic) {
-    lazy.logger.trace(`Received observer notification ${topic}`);
-
+  async observe(subject, topic) {
     let curBrowser = this.#curBrowserFn && this.#curBrowserFn();
     switch (topic) {
-      case "common-dialog-loaded":
+      case "common-dialog-loaded": {
         if (curBrowser) {
           if (
             !this.#hasCommonDialog(
@@ -178,12 +174,14 @@ export class PromptListener {
         });
 
         break;
+      }
 
-      case "domwindowopened":
+      case "domwindowopened": {
         subject.addEventListener("DOMModalDialogClosed", this);
         break;
+      }
 
-      case "geckoview-prompt-show":
+      case "geckoview-prompt-show": {
         for (let win of Services.wm.getEnumerator(null)) {
           const subjectObject = subject.wrappedJSObject;
           const prompt = win
@@ -210,6 +208,7 @@ export class PromptListener {
           }
         }
         break;
+      }
     }
   }
 
@@ -248,9 +247,13 @@ export class PromptListener {
   }
 
   #register() {
-    Services.obs.addObserver(this, "common-dialog-loaded");
-    Services.obs.addObserver(this, "domwindowopened");
-    Services.obs.addObserver(this, "geckoview-prompt-show");
+    for (const observerName of [
+      "common-dialog-loaded",
+      "domwindowopened",
+      "geckoview-prompt-show",
+    ]) {
+      Services.obs.addObserver(this, observerName);
+    }
 
     // Register event listener and save already open prompts for all already open windows.
     for (const win of Services.wm.getEnumerator(null)) {
@@ -259,21 +262,19 @@ export class PromptListener {
   }
 
   #unregister() {
-    const removeObserver = observerName => {
+    [
+      "common-dialog-loaded",
+      "domwindowopened",
+      "geckoview-prompt-show",
+    ].forEach(observerName => {
       try {
         Services.obs.removeObserver(this, observerName);
       } catch (e) {
-        lazy.logger.debug(`Failed to remove observer "${observerName}"`);
+        lazy.logger.debug(
+          `${this.constructor.name}: Failed to remove observer "${observerName}"`
+        );
       }
-    };
-
-    for (const observerName of [
-      "common-dialog-loaded",
-      "domwindowopened",
-      "geckoview-prompt-show",
-    ]) {
-      removeObserver(observerName);
-    }
+    });
 
     // Unregister event listener for all open windows
     for (const win of Services.wm.getEnumerator(null)) {

remote/webdriver-bidi/modules/root/browsingContext.sys.mjs

@@ -2127,7 +2127,7 @@ class BrowsingContextModule extends RootBiDiModule {
     }
   };
 
-  #onPromptClosed = async (eventName, data) => {
+  #onPromptClosed = (eventName, data) => {
     if (this.#subscribedEvents.has("browsingContext.userPromptClosed")) {
       const { contentBrowser, detail } = data;
       const navigableId = lazy.NavigableManager.getIdForBrowser(contentBrowser);
@@ -2136,6 +2136,12 @@ class BrowsingContextModule extends RootBiDiModule {
         return;
       }
 
+      lazy.logger.trace(
+        `[${contentBrowser.browsingContext.id}] Prompt closed (type: "${
+          detail.promptType
+        }", accepted: "${detail.accepted}")`
+      );
+
       const params = {
         context: navigableId,
         accepted: detail.accepted,
@@ -2156,6 +2162,17 @@ class BrowsingContextModule extends RootBiDiModule {
       const { contentBrowser, prompt } = data;
       const type = prompt.promptType;
 
+      prompt.getText().then(text => {
+        // We need the text to identify a user prompt when it gets
+        // randomly opened. Because on Android the text is asynchronously
+        // retrieved lets delay the logging without making the handler async.
+        lazy.logger.trace(
+          `[${contentBrowser.browsingContext.id}] Prompt opened (type: "${
+            prompt.promptType
+          }", text: "${text}")`
+        );
+      });
+
       // Do not send opened event for unsupported prompt types.
       if (!(type in UserPromptType)) {
         lazy.logger.trace(`Prompt type "${type}" not supported`);