Bug 1470213 - Collect some per-addon telemetry related to the storage.local data migration results. draft
authorLuca Greco <lgreco@mozilla.com>
Wed, 20 Jun 2018 17:13:27 +0200
changeset 812168 99268a0d5f0e764411764d6494aeb6f62e824611
parent 810123 4f6e597104dabedfecfafa2ab63dc79fd7f8bc7a
push id114468
push userluca.greco@alcacoop.it
push dateThu, 28 Jun 2018 17:32:07 +0000
bugs1470213
milestone62.0a1
Bug 1470213 - Collect some per-addon telemetry related to the storage.local data migration results. MozReview-Commit-ID: BOWPHEwE9Cg
toolkit/components/extensions/ExtensionStorageIDB.jsm
toolkit/components/extensions/child/ext-storage.js
toolkit/components/extensions/test/xpcshell/test_ext_storage_idb_data_migration.js
toolkit/components/telemetry/Events.yaml
--- a/toolkit/components/extensions/ExtensionStorageIDB.jsm
+++ b/toolkit/components/extensions/ExtensionStorageIDB.jsm
@@ -7,17 +7,16 @@
 this.EXPORTED_SYMBOLS = ["ExtensionStorageIDB"];
 
 ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
 ChromeUtils.import("resource://gre/modules/IndexedDB.jsm");
 
 XPCOMUtils.defineLazyModuleGetters(this, {
   ContextualIdentityService: "resource://gre/modules/ContextualIdentityService.jsm",
   ExtensionStorage: "resource://gre/modules/ExtensionStorage.jsm",
-  ExtensionUtils: "resource://gre/modules/ExtensionUtils.jsm",
   Services: "resource://gre/modules/Services.jsm",
   OS: "resource://gre/modules/osfile.jsm",
 });
 
 // The userContextID reserved for the extension storage (its purpose is ensuring that the IndexedDB
 // storage used by the browser.storage.local API is not directly accessible from the extension code).
 XPCOMUtils.defineLazyGetter(this, "WEBEXT_STORAGE_USER_CONTEXT_ID", () => {
   return ContextualIdentityService.getDefaultPrivateIdentity(
@@ -27,16 +26,159 @@ XPCOMUtils.defineLazyGetter(this, "WEBEX
 const IDB_NAME = "webExtensions-storage-local";
 const IDB_DATA_STORENAME = "storage-local-data";
 const IDB_VERSION = 1;
 const IDB_MIGRATE_RESULT_HISTOGRAM = "WEBEXT_STORAGE_LOCAL_IDB_MIGRATE_RESULT_COUNT";
 
 // Whether or not the installed extensions should be migrated to the storage.local IndexedDB backend.
 const BACKEND_ENABLED_PREF = "extensions.webextensions.ExtensionStorageIDB.enabled";
 
+var DataMigrationTelemetry = {
+  initialized: false,
+
+  lazyInit() {
+    if (this.initialized) {
+      return;
+    }
+    this.initialized = true;
+
+    // Ensure that these telemetry events category is enabled.
+    Services.telemetry.setEventRecordingEnabled("extensions.data", true);
+
+    this.resultHistogram = Services.telemetry.getHistogramById(IDB_MIGRATE_RESULT_HISTOGRAM);
+  },
+
+  /**
+   * Get a trimmed version of the given string if it is longer than 80 chars.
+   *
+   * @param {string} str
+   *        The original string content.
+   *
+   * @returns {string}
+   *          The trimmed version of the string when longer than 80 chars, or the given string
+   *          unmodified otherwise.
+   */
+  getTrimmedString(str) {
+    if (str.length <= 80) {
+      return str;
+    }
+
+    const length = str.length;
+    // Trim the extensionId to prevent a flood of warnings messages logged internally by recordEvent,
+    // the trimmed version is going to be composed by the first 40 chars and the last 37 and 3 dots
+    // that joins the two parts, to visually indicate that the extensionId has been trimmed.
+    return `${str.slice(0, 40)}...${str.slice(length - 37, length)}`;
+  },
+
+  /**
+   * Get the DOMException error name for a given error object.
+   *
+   * @param {Error | undefined} error
+   *        The Error object to convert into a string, or undefined if there was no error.
+   *
+   * @returns {string | undefined}
+   *          The DOMException error name (sliced to a maximum of 80 chars),
+   *          "OtherError" if the error object is not a DOMException instance,
+   *          or `undefined` if there wasn't an error.
+   */
+  getErrorName(error) {
+    if (!error) {
+      return undefined;
+    }
+
+    if (error instanceof DOMException) {
+      if (error.name.length > 80) {
+        return this.getTrimmedString(error.name);
+      }
+
+      return error.name;
+    }
+
+    return "OtherError";
+  },
+
+  /**
+   * Record telemetry related to a data migration result.
+   *
+   * @param {object} telemetryData
+   * @param {string} telemetryData.extensionId
+   *        The id of the extension that is starting to migrate.
+   */
+  recordStart(telemetryData) {
+    try {
+      const {
+        extensionId,
+      } = telemetryData;
+
+      this.lazyInit();
+      Services.telemetry.recordEvent("extensions.data", "migrateStart", "storageLocal", this.getTrimmedString(extensionId));
+    } catch (err) {
+      // Report any telemetry error on the browser console, but
+      // we treat it as a non-fatal error and we don't re-throw
+      // it to the caller.
+      Cu.reportError(err);
+    }
+  },
+
+  /**
+   * Record telemetry related to a data migration result.
+   *
+   * @param {object} telemetryData
+   * @param {string} telemetryData.backend
+   *        The backend selected ("JSONFile" or "IndexedDB").
+   * @param {boolean} telemetryData.dataMigrated
+   *        Old extension data has been migrated successfully.
+   * @param {string} telemetryData.extensionId
+   *        The id of the extension migrated.
+   * @param {Error | undefined} telemetryData.error
+   *        The error raised during the data migration, if any.
+   * @param {boolean} telemetryData.hasJSONFile
+   *        The extension has an existing JSONFile to migrate.
+   * @param {boolean} telemetryData.hasOldData
+   *        The extension's JSONFile wasn't empty.
+   * @param {string} telemetryData.histogramCategory
+   *        The histogram category for the result ("success" or "failure").
+   */
+  recordResult(telemetryData) {
+    try {
+      const {
+        backend,
+        dataMigrated,
+        extensionId,
+        error,
+        hasJSONFile,
+        hasOldData,
+        histogramCategory,
+      } = telemetryData;
+
+      this.lazyInit();
+      this.resultHistogram.add(histogramCategory);
+
+      const extra = {
+        backend,
+        data_migrated: dataMigrated ? "y" : "n",
+        has_jsonfile: hasJSONFile ? "y" : "n",
+        has_olddata: hasOldData ? "y" : "n",
+      };
+
+      if (error) {
+        extra.error_name = this.getErrorName(error);
+      }
+
+      Services.telemetry.recordEvent("extensions.data", "migrateResult", "storageLocal",
+                                     this.getTrimmedString(extensionId), extra);
+    } catch (err) {
+      // Report any telemetry error on the browser console, but
+      // we treat it as a non-fatal error and we don't re-throw
+      // it to the caller.
+      Cu.reportError(err);
+    }
+  },
+};
+
 class ExtensionStorageLocalIDB extends IndexedDB {
   onupgradeneeded(event) {
     if (event.oldVersion < 1) {
       this.createObjectStore(IDB_DATA_STORENAME);
     }
   }
 
   static openForPrincipal(storagePrincipal) {
@@ -86,20 +228,17 @@ class ExtensionStorageLocalIDB extends I
         changes[key] = {
           oldValue: oldValue && serialize ? serialize(oldValue) : oldValue,
           newValue: serialize ? serialize(items[key]) : items[key],
         };
         changed = true;
       } catch (err) {
         transaction.abort();
 
-        // Ensure that the error we throw is converted into an ExtensionError
-        // (e.g. DataCloneError instances raised from the internal IndexedDB
-        // operation have to be converted to be accessible to the extension code).
-        throw new ExtensionUtils.ExtensionError(String(err));
+        throw err;
       }
     }
 
     return changed ? changes : null;
   }
 
   /**
    * Asynchronously retrieves the values for the given storage items.
@@ -232,79 +371,104 @@ class ExtensionStorageLocalIDB extends I
  *        the ExtensionStorageLocalIDB instance.
  */
 async function migrateJSONFileData(extension, storagePrincipal) {
   let oldStoragePath;
   let oldStorageExists;
   let idbConn;
   let jsonFile;
   let hasEmptyIDB;
-  let oldDataRead = false;
-  let migrated = false;
-  let histogram = Services.telemetry.getHistogramById(IDB_MIGRATE_RESULT_HISTOGRAM);
+  let nonFatalError;
+  let hasOldData = false;
+  let dataMigrated = false;
 
   try {
     idbConn = await ExtensionStorageLocalIDB.openForPrincipal(storagePrincipal);
     hasEmptyIDB = await idbConn.isEmpty();
 
     if (!hasEmptyIDB) {
       // If the IDB backend is enabled and there is data already stored in the IDB backend,
       // there is no "going back": any data that has not been migrated will be still on disk
       // but it is not going to be migrated anymore, it could be eventually used to allow
       // a user to manually retrieve the old data file).
       return;
     }
 
+    DataMigrationTelemetry.recordStart({extensionId: extension.id});
+
     // Migrate any data stored in the JSONFile backend (if any), and remove the old data file
     // if the migration has been completed successfully.
     oldStoragePath = ExtensionStorage.getStorageFile(extension.id);
     oldStorageExists = await OS.File.exists(oldStoragePath);
 
     if (oldStorageExists) {
       Services.console.logStringMessage(
         `Migrating storage.local data for ${extension.policy.debugName}...`);
 
       jsonFile = await ExtensionStorage.getFile(extension.id);
       const data = {};
       for (let [key, value] of jsonFile.data.entries()) {
         data[key] = value;
+        hasOldData = true;
       }
-      oldDataRead = true;
+
       await idbConn.set(data);
-      migrated = true;
+      dataMigrated = true;
       Services.console.logStringMessage(
         `storage.local data successfully migrated to IDB Backend for ${extension.policy.debugName}.`);
     }
   } catch (err) {
     extension.logWarning(`Error on migrating storage.local data: ${err.message}::${err.stack}`);
-    if (oldDataRead) {
-      // If the data has been read successfully and it has been failed to be stored
-      // into the IndexedDB backend, then clear any partially stored data and reject
+
+    if (oldStorageExists && !dataMigrated) {
+      // If the data failed to be stored into the IndexedDB backend, then we clear the IndexedDB
+      // backend to allow the extension to retry the migration on its next startup, and reject
       // the data migration promise explicitly (which would prevent the new backend
       // from being enabled for this session).
       Services.qms.clearStoragesForPrincipal(storagePrincipal);
 
-      histogram.add("failure");
+      DataMigrationTelemetry.recordResult({
+        backend: "JSONFile",
+        dataMigrated,
+        extensionId: extension.id,
+        error: err,
+        hasJSONFile: oldStorageExists,
+        hasOldData,
+        histogramCategory: "failure",
+      });
 
       throw err;
     }
+
+    // This error is not preventing the extension from migrating to the IndexedDB backend,
+    // but we may still want to know that it has been triggered and include it into the
+    // telemetry data collected for the extension.
+    nonFatalError = err;
   } finally {
     // Finalize the jsonFile and clear the jsonFilePromise cached by the ExtensionStorage
     // (so that the file can be immediatelly removed when we call OS.File.remove).
     ExtensionStorage.clearCachedFile(extension.id);
     if (jsonFile) {
       jsonFile.finalize();
     }
   }
 
-  histogram.add("success");
+  DataMigrationTelemetry.recordResult({
+    backend: "IndexedDB",
+    dataMigrated,
+    extensionId: extension.id,
+    error: nonFatalError,
+    hasJSONFile: oldStorageExists,
+    hasOldData,
+    histogramCategory: "success",
+  });
 
   // If the IDB backend has been enabled, try to remove the old storage.local data file,
   // but keep using the selected backend even if it fails to be removed.
-  if (oldStorageExists && migrated) {
+  if (oldStorageExists && dataMigrated) {
     try {
       await OS.File.remove(oldStoragePath);
     } catch (err) {
       extension.logWarning(err.message);
     }
   }
 }
 
@@ -415,18 +579,16 @@ this.ExtensionStorageIDB = {
         }).catch(err => {
           // If the data migration promise is rejected, the old data has been read
           // successfully from the old JSONFile backend but it failed to be saved
           // into the IndexedDB backend (which is likely unrelated to the kind of
           // data stored and more likely a general issue with the IndexedDB backend)
           // In this case we keep the JSONFile backend enabled for this session
           // and we will retry to migrate to the IDB Backend the next time the
           // extension is being started.
-          // TODO Bug 1465129: This should be a very unlikely scenario, some telemetry
-          // data about it may be useful.
           extension.logWarning("JSONFile backend is being kept enabled by an unexpected " +
                                `IDBBackend failure: ${err.message}::${err.stack}`);
           return {backendEnabled: false};
         });
       }
 
       this.selectedBackendPromises.set(extension, promise);
     }
--- a/toolkit/components/extensions/child/ext-storage.js
+++ b/toolkit/components/extensions/child/ext-storage.js
@@ -164,21 +164,30 @@ this.storage = class extends ExtensionAP
         serialize,
       });
     };
 
     // Generate the backend-agnostic local API wrapped methods.
     const local = {};
     for (let method of ["get", "set", "remove", "clear"]) {
       local[method] = async function(...args) {
-        if (!promiseStorageLocalBackend) {
-          promiseStorageLocalBackend = getStorageLocalBackend();
+        try {
+          if (!promiseStorageLocalBackend) {
+            promiseStorageLocalBackend = getStorageLocalBackend();
+          }
+
+          const backend = await promiseStorageLocalBackend;
+          const result = await backend[method](...args);
+          return result;
+        } catch (err) {
+          // Ensure that the error we throw is converted into an ExtensionError
+          // (e.g. DataCloneError instances raised from the internal IndexedDB
+          // operation have to be converted to be accessible to the extension code).
+          throw new ExtensionUtils.ExtensionError(String(err));
         }
-        const backend = await promiseStorageLocalBackend;
-        return backend[method](...args);
       };
     }
 
     return {
       storage: {
         local,
 
         sync: {
--- a/toolkit/components/extensions/test/xpcshell/test_ext_storage_idb_data_migration.js
+++ b/toolkit/components/extensions/test/xpcshell/test_ext_storage_idb_data_migration.js
@@ -2,24 +2,32 @@
 /* vim: set sts=2 sw=2 et tw=80: */
 "use strict";
 
 // This test file verifies various scenarios related to the data migration
 // from the JSONFile backend to the IDB backend.
 
 ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
 ChromeUtils.import("resource://gre/modules/ExtensionStorage.jsm");
-ChromeUtils.import("resource://gre/modules/ExtensionStorageIDB.jsm");
+ChromeUtils.import("resource://gre/modules/TelemetryController.jsm");
+
+const {
+  ExtensionStorageIDB,
+  DataMigrationTelemetry,
+} = ChromeUtils.import("resource://gre/modules/ExtensionStorageIDB.jsm");
 
 XPCOMUtils.defineLazyModuleGetters(this, {
   OS: "resource://gre/modules/osfile.jsm",
 });
 
 const {IDB_MIGRATE_RESULT_HISTOGRAM} = ExtensionStorageIDB;
 const CATEGORIES = ["success", "failure"];
+const EVENT_CATEGORY = "extensions.data";
+const EVENT_OBJECT = "storageLocal";
+const EVENT_METHODS = ["migrateStart", "migrateResult"];
 
 async function createExtensionJSONFileWithData(extensionId, data) {
   await ExtensionStorage.set(extensionId, data);
   const jsonFile = await ExtensionStorage.getFile(extensionId);
   await jsonFile._save();
   const oldStorageFilename = ExtensionStorage.getStorageFile(extensionId);
   equal(await OS.File.exists(oldStorageFilename), true, "The old json file has been created");
 
@@ -35,18 +43,39 @@ function clearMigrationHistogram() {
 
 function assertMigrationHistogramCount(category, expectedCount) {
   const histogram = Services.telemetry.getHistogramById(IDB_MIGRATE_RESULT_HISTOGRAM);
 
   equal(histogram.snapshot().counts[CATEGORIES.indexOf(category)], expectedCount,
         `Got the expected count on category "${category}" for histogram ${IDB_MIGRATE_RESULT_HISTOGRAM}`);
 }
 
+function assertTelemetryEvents(extensionId, expectedEvents) {
+  const snapshot = Services.telemetry.snapshotEvents(Ci.nsITelemetry.DATASET_RELEASE_CHANNEL_OPTIN, true);
+
+  ok(snapshot.parent && snapshot.parent.length > 0, "Got parent telemetry events in the snapshot");
+
+  const migrateEvents = snapshot.parent.filter(([timestamp, category, method, object, value]) => {
+    return category === EVENT_CATEGORY &&
+      EVENT_METHODS.includes(method) &&
+      object === EVENT_OBJECT &&
+      value === extensionId;
+  }).map(event => {
+    return {method: event[2], extra: event[5]};
+  });
+
+  Assert.deepEqual(migrateEvents, expectedEvents, "Got the expected telemetry events");
+}
+
 add_task(async function setup() {
   Services.prefs.setBoolPref(ExtensionStorageIDB.BACKEND_ENABLED_PREF, true);
+
+  // Telemetry test setup needed to ensure that the builtin events are defined
+  // and they can be collected and verified.
+  await TelemetryController.testSetup();
 });
 
 // Test that the old data is migrated successfully to the new storage backend
 // and that the original JSONFile is being removed.
 add_task(async function test_storage_local_data_migration() {
   const EXTENSION_ID = "extension-to-be-migrated@mozilla.org";
 
   const data = {
@@ -99,16 +128,91 @@ add_task(async function test_storage_loc
         "Data stored in the ExtensionStorageIDB backend as expected");
 
   equal(await OS.File.exists(oldStorageFilename), false,
         "The old json storage file should have been removed");
 
   assertMigrationHistogramCount("success", 1);
   assertMigrationHistogramCount("failure", 0);
 
+  assertTelemetryEvents(EXTENSION_ID, [
+    {
+      method: "migrateStart",
+      extra: undefined,
+    },
+    {
+      method: "migrateResult",
+      extra: {
+        backend: "IndexedDB",
+        data_migrated: "y",
+        has_jsonfile: "y",
+        has_olddata: "y",
+      },
+    },
+  ]);
+
+  await extension.unload();
+});
+
+// Test that the extensionId included in the telemetry event is being trimmed down to 80 chars
+// as expected.
+add_task(async function test_extensionId_trimmed_in_telemetry_event() {
+  // Generated extensionId in email-like format, longer than 80 chars.
+  const EXTENSION_ID = `long.extension.id@${Array(80).fill("a").join("")}`;
+
+  const data = {"test_key_string": "test_value"};
+
+  // Store some fake data in the storage.local file backend before starting the extension.
+  await createExtensionJSONFileWithData(EXTENSION_ID, data);
+
+  async function background() {
+    const storedData = await browser.storage.local.get("test_key_string");
+
+    browser.test.assertEq("test_value", storedData.test_key_string,
+                          "Got the expected data after the storage.local data migration");
+
+    browser.test.sendMessage("storage-local-data-migrated");
+  }
+
+  let extension = ExtensionTestUtils.loadExtension({
+    manifest: {
+      permissions: ["storage"],
+      applications: {
+        gecko: {
+          id: EXTENSION_ID,
+        },
+      },
+    },
+    background,
+  });
+
+  await extension.startup();
+
+  await extension.awaitMessage("storage-local-data-migrated");
+
+  const expectedTrimmedExtensionId = DataMigrationTelemetry.getTrimmedString(EXTENSION_ID);
+
+  equal(expectedTrimmedExtensionId.length, 80, "The trimmed version of the extensionId should be 80 chars long");
+
+  assertTelemetryEvents(expectedTrimmedExtensionId, [
+    {
+      method: "migrateStart",
+      extra: undefined,
+    },
+    {
+      method: "migrateResult",
+      extra: {
+        backend: "IndexedDB",
+        data_migrated: "y",
+        has_jsonfile: "y",
+        has_olddata: "y",
+      },
+    },
+  ]);
+
   await extension.unload();
 });
 
 // Test that if the old JSONFile data file is corrupted and the old data
 // can't be successfully migrated to the new storage backend, then:
 // - the new storage backend for that extension is still initialized and enabled
 // - any new data is being stored in the new backend
 // - the old file is being renamed (with the `.corrupted` suffix that JSONFile.jsm
@@ -167,14 +271,32 @@ add_task(async function test_storage_loc
   equal(await OS.File.exists(`${oldStorageFilename}.corrupt`), true,
         "The old json storage should still be available if failed to be read");
 
   // The extension is still migrated successfully to the new backend if the file from the
   // original json file was corrupted.
   assertMigrationHistogramCount("success", 1);
   assertMigrationHistogramCount("failure", 0);
 
+  assertTelemetryEvents(EXTENSION_ID, [
+    {
+      method: "migrateStart",
+      extra: undefined,
+    },
+    {
+      method: "migrateResult",
+      extra: {
+        backend: "IndexedDB",
+        data_migrated: "y",
+        has_jsonfile: "y",
+        has_olddata: "n",
+      },
+    },
+  ]);
+
   await extension.unload();
 });
 
-add_task(function test_storage_local_data_migration_clear_pref() {
+add_task(async function test_storage_local_data_migration_clear_pref() {
   Services.prefs.clearUserPref(ExtensionStorageIDB.BACKEND_ENABLED_PREF);
+
+  await TelemetryController.testShutdown();
 });
--- a/toolkit/components/telemetry/Events.yaml
+++ b/toolkit/components/telemetry/Events.yaml
@@ -506,8 +506,27 @@ devtools.main:
     bug_numbers: [1463083]
     notification_emails: ["dev-developer-tools@lists.mozilla.org", "hkirschner@mozilla.com"]
     record_in_processes: ["main"]
     description: User has executed some JS in the Web Console.
     release_channel_collection: opt-out
     expiry_version: never
     extra_keys:
       lines: The number of lines contained in the command.
+
+extensions.data:
+  migrateResult:
+    objects: ["storageLocal"]
+    methods: ["migrateStart", "migrateResult"]
+    bug_numbers: [1470213]
+    notification_emails: ["addons-dev-internal@mozilla.com"]
+    expiry_version: "70"
+    record_in_processes: ["main"]
+    release_channel_collection: opt-out
+    extra_keys:
+      backend: The selected backend ("JSONFile" / "IndexedDB")
+      data_migrated: The old extension data has been migrated ("y" / "n")
+      error_name: A DOMException error name if any ("OtherError" for unknown errors)
+      has_jsonfile: The extension has a JSONFile ("y" / "n")
+      has_olddata: The extension had some data stored in the JSONFile ("y" / "n")
+    description: >
+      This events are sent when an extension is migrating its data to the new IndexedDB backend,
+      the value of this event is the addon id.