Bug 1802333 - Idle trigger debug logging. r=barret

To debug the idle trigger's interaction with OS sleep state, it's
helpful to know whether sleep/wake notifications were sent. This allows
most of the idle trigger activity to be logged to the console, if the
pref `messaging-system.log` is set to `debug`. The new logging will also
be used to debug the behavior reported in bug 1801301.

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

browser/components/newtab/lib/ASRouterTriggerListeners.jsm

@@ -21,6 +21,13 @@ XPCOMUtils.defineLazyModuleGetters(lazy, {
   EveryWindow: "resource:///modules/EveryWindow.jsm",
 });
 
+XPCOMUtils.defineLazyGetter(lazy, "log", () => {
+  const { Logger } = ChromeUtils.import(
+    "resource://messaging-system/lib/Logger.jsm"
+  );
+  return new Logger("ASRouterTriggerListeners");
+});
+
 const FEW_MINUTES = 15 * 60 * 1000; // 15 mins
 
 function isPrivateWindow(win) {
@@ -813,10 +820,22 @@ const ASRouterTriggerListeners = new Map([
             this._quietSince = Date.now();
           }
           this._initialized = true;
+          this.log("Initialized: ", {
+            idleTime: this._idleService.idleTime,
+            quietSince: this._quietSince,
+          });
         }
       },
       observe(subject, topic, data) {
         if (this._initialized) {
+          this.log("Heard observer notification: ", {
+            subject,
+            topic,
+            data,
+            idleTime: this._idleService.idleTime,
+            idleSince: this._idleSince,
+            quietSince: this._quietSince,
+          });
           switch (topic) {
             case "idle":
               this._idleSince = Date.now() - subject.idleTime;
@@ -855,6 +874,12 @@ const ASRouterTriggerListeners = new Map([
               }
             // fall through
             case "TabClose":
+              this.log("Tab sound changed: ", {
+                event,
+                idleTime: this._idleService.idleTime,
+                idleSince: this._idleSince,
+                quietSince: this._quietSince,
+              });
               // Maybe update time if a tab closes with sound playing.
               if (this._soundPlaying) {
                 this._quietSince = null;
@@ -865,6 +890,11 @@ const ASRouterTriggerListeners = new Map([
         }
       },
       _onActive() {
+        this.log("User is active: ", {
+          idleTime: this._idleService.idleTime,
+          idleSince: this._idleSince,
+          quietSince: this._quietSince,
+        });
         if (this._idleSince && this._quietSince) {
           const win = Services.wm.getMostRecentBrowserWindow();
           if (win && !isPrivateWindow(win) && !this._triggerTimeout) {
@@ -894,8 +924,12 @@ const ASRouterTriggerListeners = new Map([
           this._triggerHandler = null;
           this._idleSince = null;
           this._quietSince = null;
+          this.log("Uninitialized");
         }
       },
+      log(...args) {
+        lazy.log.debug("Idle trigger :>>", ...args);
+      },
 
       QueryInterface: ChromeUtils.generateQI([
         "nsIObserver",

browser/components/newtab/test/unit/unit-entry.js

@@ -1,4 +1,10 @@
-import { EventEmitter, FakePrefs, GlobalOverrider } from "test/unit/utils";
+import {
+  EventEmitter,
+  FakePrefs,
+  GlobalOverrider,
+  FakeConsoleAPI,
+  FakeLogger,
+} from "test/unit/utils";
 import Adapter from "enzyme-adapter-react-16";
 import { chaiAssertions } from "test/schemas/pings";
 import chaiJsonSchema from "chai-json-schema";
@@ -67,22 +73,6 @@ class JSWindowActorChild {
   }
 }
 
-class Logger {
-  constructor(name) {
-    this.name = name;
-  }
-
-  warn() {}
-}
-
-function ConsoleAPI() {}
-ConsoleAPI.prototype.debug = () => {};
-ConsoleAPI.prototype.trace = () => {};
-// Comment out the above prototype assignments and uncomment the ones below to get more
-// ASRouter logging in tests:
-//ConsoleAPI.prototype.debug = console.debug;
-//ConsoleAPI.prototype.trace = console.trace;
-
 // Detect plain object passed to lazy getter APIs, and set its prototype to
 // global object, and return the global object for further modification.
 // Returns the object if it's not plain object.
@@ -130,7 +120,10 @@ const TEST_GLOBAL = {
     platform: "win",
   },
   ASRouterPreferences: {
-    console: new ConsoleAPI(),
+    console: new FakeConsoleAPI({
+      maxLogLevel: "off", // set this to "debug" or "all" to get more ASRouter logging in tests
+      prefix: "ASRouter",
+    }),
   },
   BrowserUtils: {
     sendToDeviceEmailsSupported() {
@@ -183,7 +176,7 @@ const TEST_GLOBAL = {
     },
     isSuccessCode: () => true,
   },
-  ConsoleAPI,
+  ConsoleAPI: FakeConsoleAPI,
   // NB: These are functions/constructors
   // eslint-disable-next-line object-shorthand
   ContentSearchUIController: function() {},
@@ -609,7 +602,7 @@ const TEST_GLOBAL = {
     addExpirationFilter() {},
     removeExpirationFilter() {},
   },
-  Logger,
+  Logger: FakeLogger,
   getFxAccountsSingleton() {},
   AboutNewTab: {},
   Glean: {

browser/components/newtab/test/unit/utils.js

@@ -261,3 +261,60 @@ FakePerformance.prototype = {
 export function addNumberReducer(prevState = 0, action) {
   return action.type === "ADD" ? prevState + action.data : prevState;
 }
+
+export class FakeConsoleAPI {
+  static LOG_LEVELS = {
+    all: Number.MIN_VALUE,
+    debug: 2,
+    log: 3,
+    info: 3,
+    clear: 3,
+    trace: 3,
+    timeEnd: 3,
+    time: 3,
+    assert: 3,
+    group: 3,
+    groupEnd: 3,
+    profile: 3,
+    profileEnd: 3,
+    dir: 3,
+    dirxml: 3,
+    warn: 4,
+    error: 5,
+    off: Number.MAX_VALUE,
+  };
+
+  constructor({ prefix = "", maxLogLevel = "all" } = {}) {
+    this.prefix = prefix;
+    this.prefixStr = prefix ? `${prefix}: ` : "";
+    this.maxLogLevel = maxLogLevel;
+
+    for (const level of Object.keys(FakeConsoleAPI.LOG_LEVELS)) {
+      // eslint-disable-next-line no-console
+      if (typeof console[level] === "function") {
+        this[level] = this.shouldLog(level)
+          ? this._log.bind(this, level)
+          : () => {};
+      }
+    }
+  }
+  shouldLog(level) {
+    return (
+      FakeConsoleAPI.LOG_LEVELS[this.maxLogLevel] <=
+      FakeConsoleAPI.LOG_LEVELS[level]
+    );
+  }
+  _log(level, ...args) {
+    console[level](this.prefixStr, ...args); // eslint-disable-line no-console
+  }
+}
+
+export class FakeLogger extends FakeConsoleAPI {
+  constructor() {
+    super({
+      // Don't use a prefix because the first instance gets cached and reused by
+      // other consumers that would otherwise pass their own identifying prefix.
+      maxLogLevel: "off", // Change this to "debug" or "all" to get more logging in tests
+    });
+  }
+}