Bug 1254099 - Rewrite of polling changes and change Telemetry strategy
MozReview-Commit-ID: 40zMipMtKPT
--- 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],