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

--HG--
extra : moz-landing-system : lando

testing/marionette/components/marionette.js

@@ -310,7 +310,7 @@ class MarionetteParentProcess {
   }
 
   observe(subject, topic) {
-    log.debug(`Received observer notification ${topic}`);
+    log.trace(`Received observer notification ${topic}`);
 
     switch (topic) {
       case "nsPref:changed":
@@ -400,7 +400,7 @@ class MarionetteParentProcess {
         }
 
         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");
@@ -421,7 +421,7 @@ class MarionetteParentProcess {
     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();
         });
@@ -436,15 +436,15 @@ class MarionetteParentProcess {
       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) {

testing/marionette/listener.js

@@ -155,7 +155,7 @@ const loadListener = {
       // 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)) {
@@ -210,7 +210,7 @@ const loadListener = {
     }
 
     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":
@@ -347,7 +347,7 @@ const loadListener = {
     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,
@@ -440,7 +440,7 @@ const loadListener = {
  * an ID, we start the listeners. Otherwise, nothing happens.
  */
 function registerSelf() {
-  logger.debug("Frame script loaded");
+  logger.trace("Frame script loaded");
 
   sandboxes.clear();
   curContainer = {
@@ -457,7 +457,7 @@ function registerSelf() {
   }
 
   if (reply[0].outerWindowID === outerWindowID) {
-    logger.debug("Frame script registered");
+    logger.trace("Frame script registered");
     startListeners();
     sendAsyncMessage("Marionette:ListenersAttached", {outerWindowID});
   }

testing/marionette/proxy.js

@@ -144,7 +144,7 @@ proxy.AsyncMessageChannel = class {
       // 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) {
@@ -165,7 +165,7 @@ proxy.AsyncMessageChannel = class {
       // 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:

testing/marionette/server.js

@@ -395,7 +395,7 @@ class TCPConnection {
 
   log_(msg) {
     let dir = (msg.origin == Message.Origin.Client ? "->" : "<-");
-    logger.trace(`${this.id} ${dir} ${msg}`);
+    logger.debug(`${this.id} ${dir} ${msg}`);
   }
 
   toString() {

testing/marionette/sync.js

@@ -264,7 +264,7 @@ function Sleep(timeout) {
 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");