Bug 1553142 - Leverage ConsoleAPI in Remote Settings r=glasserc
authorMathieu Leplatre <mathieu@mozilla.com>
Wed, 22 May 2019 14:01:53 +0000
changeset 475201 4f7859742667c647742a604ad7e7e2ab88436d22
parent 475200 e1d9f28fbaaaa0923d91a113810496feecb80db5
child 475202 df8b61492199b1d31919104bb9dacde587d0883d
push id36057
push useraciure@mozilla.com
push dateThu, 23 May 2019 21:52:03 +0000
treeherdermozilla-central@d551d37b9ad0 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersglasserc
bugs1553142
milestone69.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 1553142 - Leverage ConsoleAPI in Remote Settings r=glasserc Differential Revision: https://phabricator.services.mozilla.com/D32138
services/common/docs/RemoteSettings.rst
services/settings/RemoteSettingsClient.jsm
services/settings/Utils.jsm
services/settings/remote-settings.js
--- a/services/common/docs/RemoteSettings.rst
+++ b/services/common/docs/RemoteSettings.rst
@@ -260,16 +260,25 @@ By default, the entries returned by ``.g
         return enabled ? entry : null;
       }
     });
 
 
 Debugging and manual testing
 ============================
 
+Logging
+-------
+
+In order to enable verbose logging, set the log level preference to ``debug``.
+
+.. code-block:: javascript
+
+    Services.prefs.setCharPref("services.settings.loglevel", "debug");
+
 Remote Settings Dev Tools
 -------------------------
 
 The Remote Settings Dev Tools extension provides some tooling to inspect synchronization statuses, to change the remote server or to switch to *preview* mode in order to sign-off pending changes. `More information on the dedicated repository <https://github.com/mozilla/remote-settings-devtools>`_.
 
 
 Trigger a synchronization manually
 ----------------------------------
--- a/services/settings/RemoteSettingsClient.jsm
+++ b/services/settings/RemoteSettingsClient.jsm
@@ -28,16 +28,17 @@ ChromeUtils.defineModuleGetter(this, "Do
 
 XPCOMUtils.defineLazyGlobalGetters(this, ["fetch"]);
 
 // IndexedDB name.
 const DB_NAME = "remote-settings";
 
 const TELEMETRY_COMPONENT = "remotesettings";
 
+XPCOMUtils.defineLazyGetter(this, "console", () => Utils.log);
 XPCOMUtils.defineLazyPreferenceGetter(this, "gServerURL",
                                       "services.settings.server");
 
 /**
  * cacheProxy returns an object Proxy that will memoize properties of the target.
  * @param {Object} target the object to wrap.
  * @returns {Proxy}
  */
@@ -207,36 +208,38 @@ class RemoteSettingsClient extends Event
     let { verifySignature = false } = options;
 
     if (syncIfEmpty && !(await Utils.hasLocalData(this))) {
       try {
         // .get() was called before we had the chance to synchronize the local database.
         // We'll try to avoid returning an empty list.
         if (await Utils.hasLocalDump(this.bucketName, this.collectionName)) {
           // Since there is a JSON dump, load it as default data.
+          console.debug("Local DB is empty, load JSON dump");
           await RemoteSettingsWorker.importJSONDump(this.bucketName, this.collectionName);
         } else {
           // There is no JSON dump, force a synchronization from the server.
+          console.debug("Local DB is empty, pull data from server");
           await this.sync({ loadDump: false });
         }
         // Either from trusted dump, or already done during sync.
         verifySignature = false;
       } catch (e) {
         // Report but return an empty list since there will be no data anyway.
         Cu.reportError(e);
         return [];
       }
     }
 
     // Read from the local DB.
     const kintoCollection = await this.openCollection();
     const { data } = await kintoCollection.list({ filters, order });
 
-    // Verify signature of local data.
     if (verifySignature) {
+      console.debug("Verify signature of local data");
       const localRecords = data.map(r => kintoCollection.cleanLocalFields(r));
       const timestamp = await kintoCollection.db.getLastModified();
       const metadata = await kintoCollection.metadata();
       await this._validateCollectionSignature([],
                                               timestamp,
                                               metadata,
                                               { localRecords });
     }
@@ -294,28 +297,30 @@ class RemoteSettingsClient extends Event
       // initial data from the application defaults.
       // This allows to avoid synchronizing the whole collection content on
       // cold start.
       if (!collectionLastModified && loadDump) {
         try {
           const imported = await RemoteSettingsWorker.importJSONDump(this.bucketName, this.collectionName);
           // The worker only returns an integer. List the imported records to build the sync event.
           if (imported > 0) {
+            console.debug(`${imported} records loaded from JSON dump`);
             ({ data: importedFromDump } = await kintoCollection.list());
           }
           collectionLastModified = await kintoCollection.db.getLastModified();
         } catch (e) {
           // Report but go-on.
           Cu.reportError(e);
         }
       }
 
       // If the data is up to date, there's no need to sync. We still need
       // to record the fact that a check happened.
       if (expectedTimestamp <= collectionLastModified) {
+        console.debug(`${this.identifier} local data is up-to-date`);
         reportStatus = UptakeTelemetry.STATUS.UP_TO_DATE;
         return;
       }
 
       // If signature verification is enabled, then add a synchronization hook
       // for incoming changes that validates the signature.
       if (this.verifySignature) {
         kintoCollection.hooks["incoming-changes"] = [async (payload, collection) => {
@@ -326,16 +331,18 @@ class RemoteSettingsClient extends Event
           const localRecords = data.map(r => kintoCollection.cleanLocalFields(r));
           await this._validateCollectionSignature(remoteRecords,
                                                   timestamp,
                                                   metadata,
                                                   { localRecords });
           // In case the signature is valid, apply the changes locally.
           return payload;
         }];
+      } else {
+        console.warn(`Signature disabled on ${this.identifier}`);
       }
 
       let syncResult;
       try {
         // Fetch changes from server, and make sure we overwrite local data.
         const strategy = Kinto.syncStrategy.SERVER_WINS;
         syncResult = await kintoCollection.sync({ remote: gServerURL, strategy, expectedTimestamp });
         if (!syncResult.ok) {
@@ -349,16 +356,17 @@ class RemoteSettingsClient extends Event
         if (e instanceof RemoteSettingsClient.InvalidSignatureError) {
           // Signature verification failed during synchronization.
           reportStatus = UptakeTelemetry.STATUS.SIGNATURE_ERROR;
           // If sync fails with a signature error, it's likely that our
           // local data has been modified in some way.
           // We will attempt to fix this by retrieving the whole
           // remote collection.
           try {
+            console.warn(`Signature verified failed for ${this.identifier}. Retry from scratch`);
             syncResult = await this._retrySyncFromScratch(kintoCollection, expectedTimestamp);
           } catch (e) {
             // If the signature fails again, or if an error occured during wiping out the
             // local data, then we report it as a *signature retry* error.
             reportStatus = UptakeTelemetry.STATUS.SIGNATURE_RETRY_ERROR;
             throw e;
           }
         } else {
@@ -387,16 +395,18 @@ class RemoteSettingsClient extends Event
       // If every changed entry is filtered, we don't even fire the event.
       if (filteredSyncResult) {
         try {
           await this.emit("sync", { data: filteredSyncResult });
         } catch (e) {
           reportStatus = UptakeTelemetry.STATUS.APPLY_ERROR;
           throw e;
         }
+      } else {
+        console.info(`All changes are filtered by JEXL expressions for ${this.identifier}`);
       }
     } catch (e) {
       // IndexedDB errors. See https://developer.mozilla.org/en-US/docs/Web/API/IDBRequest/error
       if (/(IndexedDB|AbortError|ConstraintError|QuotaExceededError|VersionError)/.test(e.message)) {
         reportStatus = UptakeTelemetry.STATUS.CUSTOM_1_ERROR;
       }
       // No specific error was tracked, mark it as unknown.
       if (reportStatus === null) {
@@ -488,16 +498,17 @@ class RemoteSettingsClient extends Event
 
     // We build a sync result as if a diff-based sync was performed.
     const syncResult = { created: [], updated: [], deleted: [] };
 
     // If the remote last_modified is newer than the local last_modified,
     // replace the local data
     const localLastModified = await kintoCollection.db.getLastModified();
     if (timestamp >= localLastModified) {
+      console.debug(`Import raw data from server for ${this.identifier}`);
       await kintoCollection.clear();
       await kintoCollection.loadDump(remoteRecords);
       await kintoCollection.db.saveLastModified(timestamp);
       await kintoCollection.db.saveMetadata(metadata);
 
       // Compare local and remote to populate the sync result
       const oldById = new Map(oldData.map(e => [e.id, e]));
       for (const r of remoteRecords) {
--- a/services/settings/Utils.jsm
+++ b/services/settings/Utils.jsm
@@ -6,20 +6,36 @@
   "Utils",
 ];
 
 const {Services} = ChromeUtils.import("resource://gre/modules/Services.jsm");
 const {XPCOMUtils} = ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
 
 XPCOMUtils.defineLazyGlobalGetters(this, ["fetch"]);
 
+// Create a new instance of the ConsoleAPI so we can control the maxLogLevel with a pref.
+// See LOG_LEVELS in Console.jsm. Common examples: "all", "debug", "info", "warn", "error".
+XPCOMUtils.defineLazyGetter(this, "log", () => {
+  const { ConsoleAPI } = ChromeUtils.import("resource://gre/modules/Console.jsm", {});
+  return new ConsoleAPI({
+    maxLogLevel: "info",
+    maxLogLevelPref: "services.settings.loglevel",
+    prefix: "services.settings",
+  });
+});
+
 var Utils = {
   CHANGES_PATH: "/buckets/monitor/collections/changes/records",
 
   /**
+   * Logger instance.
+   */
+  log,
+
+  /**
    * Check if local data exist for the specified client.
    *
    * @param {RemoteSettingsClient} client
    * @return {bool} Whether it exists or not.
    */
   async hasLocalData(client) {
     const kintoCol = await client.openCollection();
     const timestamp = await kintoCol.db.getLastModified();
--- a/services/settings/remote-settings.js
+++ b/services/settings/remote-settings.js
@@ -47,16 +47,17 @@ const TELEMETRY_SOURCE_SYNC = "settings-
 const BROADCAST_ID = "remote-settings/monitor_changes";
 
 // Signer to be used when not specified (see Ci.nsIContentSignatureVerifier).
 const DEFAULT_SIGNER = "remote-settings.content-signature.mozilla.org";
 
 XPCOMUtils.defineLazyGetter(this, "gPrefs", () => {
   return Services.prefs.getBranch(PREF_SETTINGS_BRANCH);
 });
+XPCOMUtils.defineLazyGetter(this, "console", () => Utils.log);
 XPCOMUtils.defineLazyPreferenceGetter(this, "gServerURL", PREF_SETTINGS_BRANCH + PREF_SETTINGS_SERVER);
 
 /**
  * Default entry filtering function, in charge of excluding remote settings entries
  * where the JEXL expression evaluates into a falsy value.
  * @param {Object}            entry       The Remote Settings entry to be excluded or kept.
  * @param {ClientEnvironment} environment Information about version, language, platform etc.
  * @returns {?Object} the entry or null if excluded.
@@ -102,16 +103,17 @@ function remoteSettingsFunction() {
     if (!_clients.has(collectionName)) {
       // Register a new client!
       const c = new RemoteSettingsClient(collectionName, { ...defaultOptions, ...options });
       // Store instance for later call.
       _clients.set(collectionName, c);
       // Invalidate the polling status, since we want the new collection to
       // be taken into account.
       _invalidatePolling = true;
+      console.debug(`Instantiated new client ${c.identifier}`);
     }
     return _clients.get(collectionName);
   };
 
   /**
    * Internal helper to retrieve existing instances of clients or new instances
    * with default options if possible, or `null` if bucket/collection are unknown.
    */
@@ -135,16 +137,17 @@ function remoteSettingsFunction() {
       if (dbExists || localDump) {
         return c;
       }
     }
     // Else, we cannot return a client insttance because we are not able to synchronize data in specific buckets.
     // Mainly because we cannot guess which `signerName` has to be used for example.
     // And we don't want to synchronize data for collections in the main bucket that are
     // completely unknown (ie. no database and no JSON dump).
+    console.debug(`No known client for ${bucketName}/${collectionName}`);
     return null;
   }
 
   /**
    * Main polling method, called by the ping mechanism.
    *
    * @param {Object} options
 .  * @param {Object} options.expectedTimestamp (optional) The expected timestamp to be received — used by servers for cache busting.
@@ -166,16 +169,17 @@ function remoteSettingsFunction() {
         // Backoff time has not elapsed yet.
         await UptakeTelemetry.report(TELEMETRY_COMPONENT, UptakeTelemetry.STATUS.BACKOFF, pollTelemetryArgs);
         throw new Error(`Server is asking clients to back off; retry in ${Math.ceil(remainingMilliseconds / 1000)}s.`);
       } else {
         gPrefs.clearUserPref(PREF_SETTINGS_SERVER_BACKOFF);
       }
     }
 
+    console.info("Start polling for changes");
     Services.obs.notifyObservers(null, "remote-settings:changes-poll-start", JSON.stringify({ expectedTimestamp }));
 
     // Do we have the latest version already?
     // Every time we register a new client, we have to fetch the whole list again.
     const lastEtag = _invalidatePolling ? "" : gPrefs.getCharPref(PREF_SETTINGS_LAST_ETAG, "");
 
     let pollResult;
     try {
@@ -208,16 +212,17 @@ function remoteSettingsFunction() {
 
     // Report polling success to Uptake Telemetry.
     const reportStatus = changes.length === 0 ? UptakeTelemetry.STATUS.UP_TO_DATE
                                               : UptakeTelemetry.STATUS.SUCCESS;
     await UptakeTelemetry.report(TELEMETRY_COMPONENT, reportStatus, pollTelemetryArgs);
 
     // Check if the server asked the clients to back off (for next poll).
     if (backoffSeconds) {
+      console.info("Server asks clients to backoff for ${backoffSeconds} seconds");
       const backoffReleaseTime = Date.now() + backoffSeconds * 1000;
       gPrefs.setCharPref(PREF_SETTINGS_SERVER_BACKOFF, backoffReleaseTime);
     }
 
     // Record new update time and the difference between local and server time.
     // Negative clockDifference means local time is behind server time
     // by the absolute of that value in seconds (positive means it's ahead)
     const clockDifference = Math.floor((Date.now() - serverTimeMillis) / 1000);
@@ -242,16 +247,17 @@ function remoteSettingsFunction() {
       // Start synchronization! It will be a no-op if the specified `lastModified` equals
       // the one in the local database.
       try {
         await client.maybeSync(last_modified, { loadDump, trigger });
 
         // Save last time this client was successfully synced.
         Services.prefs.setIntPref(client.lastCheckTimePref, checkedServerTimeInSeconds);
       } catch (e) {
+        console.error(e);
         if (!firstError) {
           firstError = e;
           firstError.details = change;
         }
       }
     }
 
     // Polling is done.
@@ -271,16 +277,17 @@ function remoteSettingsFunction() {
     // Save current Etag for next poll.
     if (currentEtag) {
       gPrefs.setCharPref(PREF_SETTINGS_LAST_ETAG, currentEtag);
     }
 
     // Report the global synchronization success.
     await UptakeTelemetry.report(TELEMETRY_COMPONENT, UptakeTelemetry.STATUS.SUCCESS, syncTelemetryArgs);
 
+    console.info("Polling for changes done");
     Services.obs.notifyObservers(null, "remote-settings:changes-poll-end");
   };
 
   /**
    * Returns an object with polling status information and the list of
    * known remote settings collections.
    */
   remoteSettings.inspect = async () => {
@@ -316,16 +323,17 @@ function remoteSettingsFunction() {
       collections: collections.filter(c => !!c),
     };
   };
 
   /**
    * Startup function called from nsBrowserGlue.
    */
   remoteSettings.init = () => {
+    console.info("Initialize Remote Settings");
     // Hook the Push broadcast and RemoteSettings polling.
     // When we start on a new profile there will be no ETag stored.
     // Use an arbitrary ETag that is guaranteed not to occur.
     // This will trigger a broadcast message but that's fine because we
     // will check the changes on each collection and retrieve only the
     // changes (e.g. nothing if we have a dump with the same data).
     const currentVersion = gPrefs.getStringPref(PREF_SETTINGS_LAST_ETAG, "\"0\"");
     const moduleInfo = {
@@ -343,14 +351,16 @@ var RemoteSettings = remoteSettingsFunct
 var remoteSettingsBroadcastHandler = {
   async receivedBroadcastMessage(version, broadcastID, context) {
     const { phase } = context;
     const isStartup = [
       pushBroadcastService.PHASES.HELLO,
       pushBroadcastService.PHASES.REGISTER,
     ].includes(phase);
 
+    console.info(`Push notification received (version=${version} phase=${phase})`);
+
     return RemoteSettings.pollChanges({
       expectedTimestamp: version,
       trigger: isStartup ? "startup" : "broadcast",
     });
   },
 };