Bug 1510584 - [marionette] Have a better granularity between DEBUG and TRACE logging output. r=ato
authorHenrik Skupin <mail@hskupin.info>
Thu, 29 Nov 2018 19:31:38 +0000
changeset 508066 e0192f22b98385887f84b19a76170d42843d595b
parent 508065 57f8289e1159f57271001c480258598f90305ed1
child 508067 55abd0f51161498eaa0c5a875895a54179c52b73
push id1905
push userffxbld-merge
push dateMon, 21 Jan 2019 12:33:13 +0000
treeherdermozilla-release@c2fca1944d8c [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersato
bugs1510584
milestone65.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1510584 - [marionette] Have a better granularity between DEBUG and TRACE logging output. r=ato The debug output is currently kinda polluted with lines of received events and observer notifications. Those are not usually needed by anyone beside us, but they also add little value in having additional trace output, because that mainly would only add the command and response messages. To make debug output more helpful for our users the command and response messages should appear here and not in trace. But all the additional log output lines as mentioned above we usually make use of for investigating problems should be trace only. Also a lot of existing debug output will remain unchanged. Differential Revision: https://phabricator.services.mozilla.com/D13379
testing/marionette/components/marionette.js
testing/marionette/listener.js
testing/marionette/proxy.js
testing/marionette/server.js
testing/marionette/sync.js
--- a/testing/marionette/components/marionette.js
+++ b/testing/marionette/components/marionette.js
@@ -305,17 +305,17 @@ class MarionetteParentProcess {
 
       default:
         log.warn("Unknown IPC message to parent process: " + name);
         return null;
     }
   }
 
   observe(subject, topic) {
-    log.debug(`Received observer notification ${topic}`);
+    log.trace(`Received observer notification ${topic}`);
 
     switch (topic) {
       case "nsPref:changed":
         if (this.enabled) {
           this.init(false);
         } else {
           this.uninit();
         }
@@ -395,17 +395,17 @@ class MarionetteParentProcess {
         for (let win of Services.wm.getEnumerator(null)) {
           if (win.document.documentURI == "chrome://gfxsanity/content/sanityparent.html") {
             this.gfxWindow = win;
             break;
           }
         }
 
         if (this.gfxWindow) {
-          log.debug("GFX sanity window detected, waiting until it has been closed...");
+          log.trace("GFX sanity window detected, waiting until it has been closed...");
           Services.obs.addObserver(this, "domwindowclosed");
         } else {
           Services.obs.addObserver(this, "xpcom-will-shutdown");
           this.finalUIStartup = true;
           this.init();
         }
 
         break;
@@ -416,40 +416,40 @@ class MarionetteParentProcess {
         break;
     }
   }
 
   suppressSafeModeDialog(win) {
     win.addEventListener("load", () => {
       if (win.document.getElementById("safeModeDialog")) {
         // accept the dialog to start in safe-mode
-        log.debug("Safe mode detected, supressing dialog");
+        log.trace("Safe mode detected, supressing dialog");
         win.setTimeout(() => {
           win.document.documentElement.getButton("accept").click();
         });
       }
     }, {once: true});
   }
 
   init(quit = true) {
     if (this.running || !this.enabled || !this.finalUIStartup) {
       log.debug(`Init aborted (running=${this.running}, ` +
                 `enabled=${this.enabled}, finalUIStartup=${this.finalUIStartup})`);
       return;
     }
 
-    log.debug(`Waiting for delayed startup...`);
+    log.trace(`Waiting until startup recorder finished recording startup scripts...`);
     Services.tm.idleDispatchToMainThread(async () => {
       let startupRecorder = Promise.resolve();
       if ("@mozilla.org/test/startuprecorder;1" in Cc) {
-        log.debug(`Waiting for startup tests...`);
         startupRecorder = Cc["@mozilla.org/test/startuprecorder;1"]
             .getService().wrappedJSObject.done;
       }
       await startupRecorder;
+      log.trace(`All scripts recorded.`);
 
       if (MarionettePrefs.recommendedPrefs) {
         for (let [k, v] of RECOMMENDED_PREFS) {
           if (!Preferences.isSet(k)) {
             log.debug(`Setting recommended pref ${k} to ${v}`);
             Preferences.set(k, v);
             this.alteredPrefs.add(k);
           }
--- a/testing/marionette/listener.js
+++ b/testing/marionette/listener.js
@@ -150,17 +150,17 @@ const loadListener = {
     } else {
       // The frame script has been moved to a differnt content process.
       // Due to the time it takes to re-register the browser in Marionette,
       // it can happen that page load events are missed before the listeners
       // are getting attached again. By checking the document readyState the
       // command can return immediately if the page load is already done.
       let readyState = content.document.readyState;
       let documentURI = content.document.documentURI;
-      logger.debug(truncate`Check readyState ${readyState} for ${documentURI}`);
+      logger.trace(truncate`Check readyState ${readyState} for ${documentURI}`);
       // If the page load has already finished, don't setup listeners and
       // timers but return immediatelly.
       if (this.handleReadyState(readyState, documentURI)) {
         return;
       }
 
       addEventListener("DOMContentLoaded", loadListener, true);
       addEventListener("pageshow", loadListener, true);
@@ -205,17 +205,17 @@ const loadListener = {
     // Only care about events from the currently selected browsing context,
     // whereby some of those do not bubble up to the window.
     if (event.target != curContainer.frame &&
         event.target != curContainer.frame.document) {
       return;
     }
 
     let location = event.target.documentURI || event.target.location.href;
-    logger.debug(truncate`Received DOM event ${event.type} for ${location}`);
+    logger.trace(truncate`Received DOM event ${event.type} for ${location}`);
 
     switch (event.type) {
       case "beforeunload":
         this.seenBeforeUnload = true;
         break;
 
       case "unload":
         this.seenUnload = true;
@@ -342,17 +342,17 @@ const loadListener = {
     }
   },
 
   observe(subject, topic) {
     const win = curContainer.frame;
     const winID = subject.QueryInterface(Ci.nsISupportsPRUint64).data;
     const curWinID = win.windowUtils.outerWindowID;
 
-    logger.debug(`Received observer notification ${topic}`);
+    logger.trace(`Received observer notification ${topic}`);
 
     switch (topic) {
       // In the case when the currently selected frame is closed,
       // there will be no further load events. Stop listening immediately.
       case "outer-window-destroyed":
         if (curWinID === winID) {
           this.stop();
           sendOk(this.commandID);
@@ -435,34 +435,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() {
-  logger.debug("Frame script loaded");
+  logger.trace("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");
+    logger.trace("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.
 //
--- a/testing/marionette/proxy.js
+++ b/testing/marionette/proxy.js
@@ -139,17 +139,17 @@ proxy.AsyncMessageChannel = class {
           default:
             throw new TypeError(`Unknown async response type: ${type}`);
         }
       };
 
       // The currently selected tab or window is closing. Make sure to wait
       // until it's fully gone.
       this.closeHandler = async ({type, target}) => {
-        log.debug(`Received DOM event ${type} for ${target}`);
+        log.trace(`Received DOM event ${type} for ${target}`);
 
         let messageManager;
         switch (type) {
           case "unload":
             messageManager = this.browser.window.messageManager;
             break;
           case "TabClose":
             messageManager = this.browser.messageManager;
@@ -160,17 +160,17 @@ proxy.AsyncMessageChannel = class {
         this.removeHandlers();
         resolve();
       };
 
       // A modal or tab modal dialog has been opened. To be able to handle it,
       // the active command has to be aborted. Therefore remove all handlers,
       // and cancel any ongoing requests in the listener.
       this.dialogueObserver_ = (subject, topic) => {
-        log.debug(`Received observer notification ${topic}`);
+        log.trace(`Received observer notification ${topic}`);
 
         this.removeAllListeners_();
         // TODO(ato): It's not ideal to have listener specific behaviour here:
         this.sendAsync("cancelRequest");
 
         this.removeHandlers();
         resolve();
       };
--- a/testing/marionette/server.js
+++ b/testing/marionette/server.js
@@ -390,16 +390,16 @@ class TCPConnection {
    *     The payload to ship.
    */
   sendRaw(payload) {
     this.conn.send(payload);
   }
 
   log_(msg) {
     let dir = (msg.origin == Message.Origin.Client ? "->" : "<-");
-    logger.trace(`${this.id} ${dir} ${msg}`);
+    logger.debug(`${this.id} ${dir} ${msg}`);
   }
 
   toString() {
     return `[object TCPConnection ${this.id}]`;
   }
 }
 this.TCPConnection = TCPConnection;
--- a/testing/marionette/sync.js
+++ b/testing/marionette/sync.js
@@ -259,17 +259,17 @@ function Sleep(timeout) {
  *     and the window message manager when closing a chrome window.
  *
  * @return {Promise}
  *     A promise that resolves when the message manager has been destroyed.
  */
 function MessageManagerDestroyedPromise(messageManager) {
   return new Promise(resolve => {
     function observe(subject, topic) {
-      log.debug(`Received observer notification ${topic}`);
+      log.trace(`Received observer notification ${topic}`);
 
       if (subject == messageManager) {
         Services.obs.removeObserver(this, "message-manager-disconnect");
         resolve();
       }
     }
 
     Services.obs.addObserver(observe, "message-manager-disconnect");