Bug 1254099 - Rewrite of polling changes and change Telemetry strategy draft
authorMathieu Leplatre <mathieu@mozilla.com>
Fri, 03 Feb 2017 12:45:08 +0100
changeset 470232 3627f7ddcb5e1b53608feaf51362f02a0346200e
parent 469723 0ac71d66154a118c88bf903766f0788f8b9de58a
child 470335 3a33c2580a16ffdb4f0b6b391b48b2b1a212686a
push id43970
push usermleplatre@mozilla.com
push dateFri, 03 Feb 2017 11:45:46 +0000
bugs1254099
milestone54.0a1
Bug 1254099 - Rewrite of polling changes and change Telemetry strategy MozReview-Commit-ID: 40zMipMtKPT
services/common/blocklist-updater.js
services/common/tests/unit/head_helpers.js
services/common/tests/unit/test_blocklist_updater.js
toolkit/components/telemetry/Histograms.json
--- a/services/common/blocklist-updater.js
+++ b/services/common/blocklist-updater.js
@@ -6,98 +6,127 @@ this.EXPORTED_SYMBOLS = ["checkVersions"
 
 const { classes: Cc, Constructor: CC, interfaces: Ci, utils: Cu } = Components;
 
 Cu.import("resource://gre/modules/Services.jsm");
 Cu.import("resource://gre/modules/Task.jsm");
 Cu.importGlobalProperties(["fetch"]);
 const BlocklistClients = Cu.import("resource://services-common/blocklist-clients.js", {});
 
-const SERVICES_SETTINGS_CHANGES_FAILED  = 2;
 const PREF_SETTINGS_SERVER              = "services.settings.server";
 const PREF_BLOCKLIST_CHANGES_PATH       = "services.blocklist.changes.path";
 const PREF_BLOCKLIST_LAST_UPDATE        = "services.blocklist.last_update_seconds";
 const PREF_BLOCKLIST_LAST_ETAG          = "services.blocklist.last_etag";
 const PREF_BLOCKLIST_CLOCK_SKEW_SECONDS = "services.blocklist.clock_skew_seconds";
 
+// Telemetry report result.
+const SERVICE_SETTINGS_POLLING_SUCCESS          = 0;
+const SERVICE_SETTINGS_POLLING_NETWORK_FAILURE  = 1;
+const SERVICE_SETTINGS_POLLING_SERVER_FAILURE   = 2;
 
 const gBlocklistClients = {
   [BlocklistClients.OneCRLBlocklistClient.collectionName]: BlocklistClients.OneCRLBlocklistClient,
   [BlocklistClients.AddonBlocklistClient.collectionName]: BlocklistClients.AddonBlocklistClient,
   [BlocklistClients.GfxBlocklistClient.collectionName]: BlocklistClients.GfxBlocklistClient,
   [BlocklistClients.PluginBlocklistClient.collectionName]: BlocklistClients.PluginBlocklistClient,
   [BlocklistClients.PinningPreloadClient.collectionName]: BlocklistClients.PinningPreloadClient
 };
 
 // Add a blocklist client for testing purposes. Do not use for any other purpose
 this.addTestBlocklistClient = (name, client) => { gBlocklistClients[name] = client; }
 
+
+function* pollChanges(url, lastEtag) {
+  //
+  // Fetch a versionInfo object from the server that looks like:
+  // {"data":[
+  //   {
+  //     "host":"kinto-ota.dev.mozaws.net",
+  //     "last_modified":1450717104423,
+  //     "bucket":"blocklists",
+  //     "collection":"certificates"
+  //    }]}
+
+  // Use ETag to obtain a `304 Not modified` when no change occurred.
+  const headers = {};
+  if (lastEtag) {
+    headers["If-None-Match"] = lastEtag;
+  }
+  const response = yield fetch(url, {headers});
+
+  let versionInfo = [];
+  // If no changes since last time, go on with empty list of changes.
+  if (response.status != 304) {
+    let payload;
+    try {
+      payload = yield response.json();
+    } catch (e) {}
+    if (!payload.hasOwnProperty("data")) {
+      // If the server is failing, the JSON response might not contain the
+      // expected data (e.g. error response - Bug 1259145)
+      throw new Error(`Server error response ${JSON.stringify(payload)}`);
+    }
+    versionInfo = payload.data;
+  }
+  // The server should always return ETag. But we've had situations where the CDN
+  // was interfering.
+  const currentEtag = response.headers.has("ETag") ? response.headers.get("ETag") : undefined;
+  const serverTimeMillis = Date.parse(response.headers.get("Date"));
+
+  dump(`${versionInfo}\n`);
+  return {versionInfo, currentEtag, serverTimeMillis};
+}
+
+
 // This is called by the ping mechanism.
 // returns a promise that rejects if something goes wrong
 this.checkVersions = function() {
   return Task.spawn(function* syncClients() {
-    // Fetch a versionInfo object that looks like:
-    // {"data":[
-    //   {
-    //     "host":"kinto-ota.dev.mozaws.net",
-    //     "last_modified":1450717104423,
-    //     "bucket":"blocklists",
-    //     "collection":"certificates"
-    //    }]}
+
     // Right now, we only use the collection name and the last modified info
     const kintoBase = Services.prefs.getCharPref(PREF_SETTINGS_SERVER);
     const changesEndpoint = kintoBase + Services.prefs.getCharPref(PREF_BLOCKLIST_CHANGES_PATH);
 
-    // Use ETag to obtain a `304 Not modified` when no change occurred.
-    const headers = {};
+    let lastEtag;
     if (Services.prefs.prefHasUserValue(PREF_BLOCKLIST_LAST_ETAG)) {
-      const lastEtag = Services.prefs.getCharPref(PREF_BLOCKLIST_LAST_ETAG);
-      if (lastEtag) {
-        headers["If-None-Match"] = lastEtag;
-      }
+      lastEtag = Services.prefs.getCharPref(PREF_BLOCKLIST_LAST_ETAG);
     }
 
-    let response;
-
+    let pollResult, pollError;
     try {
-      response = yield fetch(changesEndpoint, {headers});
+      pollResult = yield pollChanges(changesEndpoint, lastEtag);
+    } catch (e) {
+      pollError = e;
+    }
+    // Report polling status to Telemetry.
+    const report =  pollResult ? SERVICE_SETTINGS_POLLING_SUCCESS
+                               : /Server/.test(pollError.message) ? SERVICE_SETTINGS_POLLING_SERVER_FAILURE
+                                                                  : SERVICE_SETTINGS_POLLING_NETWORK_FAILURE;
+    Services.telemetry
+      .getHistogramById("SERVICE_SETTINGS_POLLING_RESULT")
+      .add(report);
 
-      // No changes since last time. Go on with empty list of changes.
-      if (response.status == 304) {
-        versionInfo = {data: []};
-      } else {
-        versionInfo = yield response.json();
-      }
-    } catch (e) {
-      Services.telemetry
-          .getHistogramById("SERVICES_SETTINGS_SUCCESS")
-          .add(SERVICES_SETTINGS_CHANGES_FAILED);
-      throw e;
+    if (pollError) {
+      // No need to go further.
+      throw new Error(`Polling for changes failed: ${pollError.message}.`);
     }
 
-    // If the server is failing, the JSON response might not contain the
-    // expected data (e.g. error response - Bug 1259145)
-    if (!response || !versionInfo.hasOwnProperty("data")) {
-      Services.telemetry
-          .getHistogramById("SERVICES_SETTINGS_SUCCESS")
-          .add(SERVICES_SETTINGS_CHANGES_FAILED);
-      throw new Error("Polling for changes failed.");
-    }
+    const {serverTimeMillis, versionInfo, currentEtag} = pollResult;
 
-    // Record new update time and the difference between local and server time
-    const serverTimeMillis = Date.parse(response.headers.get("Date"));
-
-    // negative clockDifference means local time is behind server time
+    // 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);
     Services.prefs.setIntPref(PREF_BLOCKLIST_CLOCK_SKEW_SECONDS, clockDifference);
     Services.prefs.setIntPref(PREF_BLOCKLIST_LAST_UPDATE, serverTimeMillis / 1000);
 
+    // Iterate through the collections version info and initiate a synchronization
+    // on the related blocklist client.
     let firstError;
-    for (let collectionInfo of versionInfo.data) {
+    for (const collectionInfo of versionInfo) {
       const {bucket, collection, last_modified: lastModified} = collectionInfo;
       const client = gBlocklistClients[collection];
       if (client && client.bucketName == bucket) {
         try {
           yield client.maybeSync(lastModified, serverTimeMillis);
         } catch (e) {
           if (!firstError) {
             firstError = e;
@@ -106,14 +135,13 @@ this.checkVersions = function() {
       }
     }
     if (firstError) {
       // cause the promise to reject by throwing the first observed error
       throw firstError;
     }
 
     // Save current Etag for next poll.
-    if (response.headers.has("ETag")) {
-      const currentEtag = response.headers.get("ETag");
+    if (currentEtag) {
       Services.prefs.setCharPref(PREF_BLOCKLIST_LAST_ETAG, currentEtag);
     }
   });
 };
--- a/services/common/tests/unit/head_helpers.js
+++ b/services/common/tests/unit/head_helpers.js
@@ -174,22 +174,22 @@ ensureStartOverKeepsIdentity();
 function getHistogramSnapshot(histogramName) {
   return Cc["@mozilla.org/base/telemetry;1"]
            .getService(Ci.nsITelemetry)
            .getHistogramById(histogramName)
            .snapshot();
 }
 
 function getDefaultIncrements(snapshot) {
-  let increments = {};
+  const increments = {};
   for (let i = 0; i < snapshot.max; i++) {
     increments[i] = 0;
   }
   return increments;
 }
 
 function checkHistogramIncrements(snapshot1, snapshot2, expectedIncrements) {
-  for (let key in expectedIncrements) {
-    let expected = expectedIncrements[key];
-    let actual = snapshot2.counts[key] - snapshot1.counts[key];
+  for (const key in expectedIncrements) {
+    const expected = expectedIncrements[key];
+    const actual = snapshot2.counts[key] - snapshot1.counts[key];
     equal(expected, actual, `check histogram count for ${key}`);
   }
 }
--- a/services/common/tests/unit/test_blocklist_updater.js
+++ b/services/common/tests/unit/test_blocklist_updater.js
@@ -2,17 +2,20 @@ Cu.import("resource://testing-common/htt
 
 var server;
 
 const PREF_SETTINGS_SERVER = "services.settings.server";
 const PREF_LAST_UPDATE = "services.blocklist.last_update_seconds";
 const PREF_LAST_ETAG = "services.blocklist.last_etag";
 const PREF_CLOCK_SKEW_SECONDS = "services.blocklist.clock_skew_seconds";
 
-const SERVICES_SETTINGS_CHANGES_FAILED = 2;
+// Telemetry report result.
+const SERVICE_SETTINGS_POLLING_SUCCESS          = 0;
+const SERVICE_SETTINGS_POLLING_NETWORK_FAILURE  = 1;
+const SERVICE_SETTINGS_POLLING_SERVER_FAILURE   = 2;
 
 // Check to ensure maybeSync is called with correct values when a changes
 // document contains information on when a collection was last modified
 add_task(function* test_check_maybeSync() {
   const changesPath = "/v1/buckets/monitor/collections/changes/records";
 
   // register a handler
   function handleResponse(serverTimeMillis, request, response) {
@@ -64,16 +67,18 @@ add_task(function* test_check_maybeSync(
         do_check_eq(lastModified, 1000);
         do_check_eq(serverTime, 2000);
         resolve();
       }
     });
     updater.checkVersions();
   });
 
+  let startHistogram = getHistogramSnapshot("SERVICE_SETTINGS_POLLING_RESULT");
+
   // ensure we get the maybeSync call
   yield syncPromise;
 
   // check the last_update is updated
   do_check_eq(Services.prefs.getIntPref(PREF_LAST_UPDATE), 2);
 
   // How does the clock difference look?
   let endTime = Date.now();
@@ -104,45 +109,51 @@ add_task(function* test_check_maybeSync(
       code: 503,
       errno: 999,
       error: "Service Unavailable",
     }));
     response.setStatusLine(null, 503, "Service Unavailable");
   }
   server.registerPathHandler(changesPath, simulateErrorResponse);
 
-  let startHistogram = getHistogramSnapshot("SERVICES_SETTINGS_SUCCESS");
   // checkVersions() fails with adequate error.
   let error;
   try {
     yield updater.checkVersions();
   } catch (e) {
     error = e;
   }
-  do_check_eq(error.message, "Polling for changes failed.");
+  do_check_true(/Polling for changes failed/.test(error.message));
   // When an error occurs, last update was not overwritten (see Date header above).
   do_check_eq(Services.prefs.getIntPref(PREF_LAST_UPDATE), 2);
 
-  let endHistogram = getHistogramSnapshot("SERVICES_SETTINGS_SUCCESS");
-
-  // ensure that we've accumulated the correct telemetry
-  let expectedIncrements = getDefaultIncrements(startHistogram);
-  expectedIncrements[SERVICES_SETTINGS_CHANGES_FAILED] = 1;
-  checkHistogramIncrements(startHistogram, endHistogram, expectedIncrements);
-
   // check negative clock skew times
 
   // set to a time in the future
   server.registerPathHandler(changesPath, handleResponse.bind(null, Date.now() + 10000));
 
   yield updater.checkVersions();
 
   clockDifference = Services.prefs.getIntPref(PREF_CLOCK_SKEW_SECONDS);
   // we previously set the serverTime to Date.now() + 10000 ms past epoch
   do_check_true(clockDifference <= 0 && clockDifference >= -10);
+
+  // Simulate a network error (to check telemetry report).
+  Services.prefs.setCharPref(PREF_SETTINGS_SERVER, "http://localhost:42/v1");
+  try {
+    yield updater.checkVersions();
+  } catch (e) {}
+
+  const endHistogram = getHistogramSnapshot("SERVICE_SETTINGS_POLLING_RESULT");
+  // ensure that we've accumulated the correct telemetry
+  const expectedIncrements = getDefaultIncrements(startHistogram);
+  expectedIncrements[SERVICE_SETTINGS_POLLING_SUCCESS] = 3;
+  expectedIncrements[SERVICE_SETTINGS_POLLING_SERVER_FAILURE] = 1;
+  expectedIncrements[SERVICE_SETTINGS_POLLING_NETWORK_FAILURE] = 1;
+  checkHistogramIncrements(startHistogram, endHistogram, expectedIncrements);
 });
 
 function run_test() {
   // Set up an HTTP Server
   server = new HttpServer();
   server.start(-1);
 
   run_next_test();
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -8883,23 +8883,23 @@
     "n_buckets": 20,
     "description": "Tracking how ServiceWorkerRegistrar loads data before the first content is shown. File bugs in Core::DOM in case of a Telemetry regression."
   },
   "SERVICE_WORKER_REQUEST_PASSTHROUGH": {
     "expires_in_version": "50",
     "kind": "boolean",
     "description": "Intercepted fetch sending back same Request object. File bugs in Core::DOM in case of a Telemetry regression."
   },
-  "SERVICES_SETTINGS_SUCCESS": {
-    "expires_in_version": "never",
-    "kind": "enumerated",
-    "n_values": 20,
+  "SERVICE_SETTINGS_POLLING_RESULT": {
+    "expires_in_version": "never",
+    "kind": "enumerated",
+    "n_values": 5,
     "alert_emails": ["seceng-telemetry@mozilla.com"],
     "bug_numbers": [1254099],
-    "description": "Services settings (kinto) sync success information (0=Sync completed, 1=Sync failed, 2='Changes' check failed, 3=Signature verification failed, 4=Retry signature verification failed, 5=OneCRL sync failed, 6=OneCRL entry failed, 7=Addons sync failed, 8=Gfx sync failed, 9=Plugins sync failed"
+    "description": "Services settings polling result information (0=Success, 1=Network error, 2=Server response error"
   },
   "E10S_STATUS": {
     "alert_emails": ["firefox-dev@mozilla.org"],
     "expires_in_version": "never",
     "kind": "enumerated",
     "n_values": 12,
     "releaseChannelCollection": "opt-out",
     "bug_numbers": [1241294],