Bug 1464469 - Prefix frame script logs with the outerWindowID. r?whimboo draft
authorAndreas Tolfsen <ato@sny.no>
Wed, 06 Jun 2018 14:45:46 +0100
changeset 808106 01f3fd6b6407bb28b1ade11f96f55add11a8ab89
parent 808105 5bf575a2ecec75f60a0e1af35ad7cbe25727761c
push id113277
push userbmo:ato@sny.no
push dateMon, 18 Jun 2018 12:24:24 +0000
reviewerswhimboo
bugs1464469
milestone62.0a1
Bug 1464469 - Prefix frame script logs with the outerWindowID. r?whimboo This change will prefix all log entries originating from a frame script with the content browser's outerWindowID. That makes it easier to for example keep of the origin of web DOM event logging. Whilst it is true that Marionette operates in one browser context at a time, the frequent context switches make it a cognitive challenge to keep track of which browser is currently active. This is especially true at the moment when Marionette does not have the capability to uniquely identify a browser. The intention is to change from using the outerWindowID, which changes when a content browser undergoes a remoteness change, to using a unique identifier for the browser once https://bugzil.la/marionette-window-tracking is available. MozReview-Commit-ID: 813zALY3I9i
testing/marionette/listener.js
--- a/testing/marionette/listener.js
+++ b/testing/marionette/listener.js
@@ -6,17 +6,16 @@
 /* global XPCNativeWrapper */
 
 "use strict";
 
 const winUtil = content.QueryInterface(Ci.nsIInterfaceRequestor)
     .getInterface(Ci.nsIDOMWindowUtils);
 
 ChromeUtils.import("resource://gre/modules/FileUtils.jsm");
-ChromeUtils.import("resource://gre/modules/Log.jsm");
 ChromeUtils.import("resource://gre/modules/Services.jsm");
 ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
 
 ChromeUtils.import("chrome://marionette/content/accessibility.js");
 ChromeUtils.import("chrome://marionette/content/action.js");
 ChromeUtils.import("chrome://marionette/content/atom.js");
 ChromeUtils.import("chrome://marionette/content/capture.js");
 const {
@@ -34,22 +33,25 @@ const {
   UnknownError,
 } = ChromeUtils.import("chrome://marionette/content/error.js", {});
 ChromeUtils.import("chrome://marionette/content/evaluate.js");
 ChromeUtils.import("chrome://marionette/content/event.js");
 const {ContentEventObserverService} = ChromeUtils.import("chrome://marionette/content/dom.js", {});
 const {pprint, truncate} = ChromeUtils.import("chrome://marionette/content/format.js", {});
 ChromeUtils.import("chrome://marionette/content/interaction.js");
 ChromeUtils.import("chrome://marionette/content/legacyaction.js");
+const {Log} = ChromeUtils.import("chrome://marionette/content/log.js", {});
 ChromeUtils.import("chrome://marionette/content/navigate.js");
 ChromeUtils.import("chrome://marionette/content/proxy.js");
 ChromeUtils.import("chrome://marionette/content/session.js");
 
+XPCOMUtils.defineLazyGetter(this, "logger", () => Log.getWithPrefix(outerWindowID));
 XPCOMUtils.defineLazyGlobalGetters(this, ["URL"]);
 
+let {outerWindowID} = winUtil;
 let curContainer = {frame: content, shadowRoot: null};
 
 // Listen for click event to indicate one click has happened, so actions
 // code can send dblclick event
 addEventListener("click", event.DoubleClickTracker.setClick);
 addEventListener("dblclick", event.DoubleClickTracker.resetClick);
 addEventListener("unload", event.DoubleClickTracker.resetClick, true);
 
@@ -73,25 +75,16 @@ Object.defineProperty(this, "capabilitie
   configurable: true,
 });
 
 let legacyactions = new legacyaction.Chain();
 
 // last touch for each fingerId
 let multiLast = {};
 
-// TODO: Log.jsm is not e10s compatible (see https://bugzil.la/1411513),
-// query the parent process for the current log level
-const logger = Log.repository.getLogger("Marionette");
-if (logger.ownAppenders.length == 0) {
-  let log = Services.cpmm.initialProcessData["Marionette:Log"];
-  logger.level = log.level;
-  logger.addAppender(new Log.DumpAppender());
-}
-
 // sandbox storage and name of the current sandbox
 const sandboxes = new Sandboxes(() => curContainer.frame);
 
 const eventObservers = new ContentEventObserverService(
     content, sendAsyncMessage.bind(this));
 
 /**
  * The load listener singleton helps to keep track of active page load
@@ -440,34 +433,34 @@ const loadListener = {
 };
 
 /**
  * Called when listener is first started up.  The listener sends its
  * unique window ID and its current URI to the actor.  If the actor returns
  * an ID, we start the listeners. Otherwise, nothing happens.
  */
 function registerSelf() {
-  let {outerWindowID} = winUtil;
-  logger.debug(`Register listener.js for window ${outerWindowID}`);
+  logger.debug("Frame script loaded");
 
   sandboxes.clear();
   curContainer = {
     frame: content,
     shadowRoot: null,
   };
   legacyactions.mouseEventsOnly = false;
   action.inputStateMap = new Map();
   action.inputsToCancel = [];
 
   let reply = sendSyncMessage("Marionette:Register", {outerWindowID});
   if (reply.length == 0) {
     logger.error("No reply from Marionette:Register");
   }
 
   if (reply[0].outerWindowID === outerWindowID) {
+    logger.debug("Frame script registered");
     startListeners();
     sendAsyncMessage("Marionette:ListenersAttached", {outerWindowID});
   }
 }
 
 // Eventually we will not have a closure for every single command,
 // but use a generic dispatch for all listener commands.
 //
@@ -1584,47 +1577,47 @@ function flushRendering() {
     let afterPaintWasPending = utils.isMozAfterPaintPending;
 
     let root = win.document.documentElement;
     if (root) {
       try {
         // Flush pending restyles and reflows for this window
         root.getBoundingClientRect();
       } catch (e) {
-        logger.warning(`flushWindow failed: ${e}`);
+        logger.error("flushWindow failed", e);
       }
     }
 
     if (!afterPaintWasPending && utils.isMozAfterPaintPending) {
       anyPendingPaintsGeneratedInDescendants = true;
     }
 
     for (let i = 0; i < win.frames.length; ++i) {
       flushWindow(win.frames[i]);
     }
   }
   flushWindow(content);
 
   if (anyPendingPaintsGeneratedInDescendants &&
       !windowUtils.isMozAfterPaintPending) {
-    logger.error("Internal error: descendant frame generated a MozAfterPaint event, but the root document doesn't have one!");
+    logger.error("Descendant frame generated a MozAfterPaint event, " +
+        "but the root document doesn't have one!");
   }
 
   logger.debug(`flushRendering ${windowUtils.isMozAfterPaintPending}`);
   return windowUtils.isMozAfterPaintPending;
 }
 
 async function reftestWait(url, remote) {
   let win = curContainer.frame;
   let document = curContainer.frame.document;
 
   let windowUtils = content.QueryInterface(Ci.nsIInterfaceRequestor)
       .getInterface(Ci.nsIDOMWindowUtils);
 
-
   let reftestWait = false;
 
   if (document.location.href !== url || document.readyState != "complete") {
     logger.debug(truncate`Waiting for page load of ${url}`);
     await new Promise(resolve => {
       let maybeResolve = event => {
         if (event.target === curContainer.frame.document &&
             event.target.location.href === url) {