Bug 1254099 - Add telemetry for failed Kinto collection sync. r = MattN
MozReview-Commit-ID: 8vAuTImx7IH
--- a/services/common/blocklist-clients.js
+++ b/services/common/blocklist-clients.js
@@ -18,16 +18,23 @@ Cu.import("resource://gre/modules/Servic
const { Task } = Cu.import("resource://gre/modules/Task.jsm");
const { OS } = Cu.import("resource://gre/modules/osfile.jsm");
Cu.importGlobalProperties(["fetch"]);
const { loadKinto } = Cu.import("resource://services-common/kinto-offline-client.js");
const { KintoHttpClient } = Cu.import("resource://services-common/kinto-http-client.js");
const { CanonicalJSON } = Components.utils.import("resource://gre/modules/CanonicalJSON.jsm");
+const SERVICES_SETTINGS_SYNC_SIG_FAIL = 3;
+const SERVICES_SETTINGS_SYNC_RETRY_SIG_FAIL = 4;
+const SERVICES_SETTINGS_SYNC_ONECRL_FAIL = 5;
+const SERVICES_SETTINGS_SYNC_ONECRL_ENTRY = 6;
+const SERVICES_SETTINGS_SYNC_ADDONS_FAIL = 7;
+const SERVICES_SETTINGS_SYNC_GFX_FAIL = 8;
+const SERVICES_SETTINGS_SYNC_PLUGINS_FAIL = 9;
const PREF_SETTINGS_SERVER = "services.settings.server";
const PREF_BLOCKLIST_BUCKET = "services.blocklist.bucket";
const PREF_BLOCKLIST_ONECRL_COLLECTION = "services.blocklist.onecrl.collection";
const PREF_BLOCKLIST_ONECRL_CHECKED_SECONDS = "services.blocklist.onecrl.checked";
const PREF_BLOCKLIST_ADDONS_COLLECTION = "services.blocklist.addons.collection";
const PREF_BLOCKLIST_ADDONS_CHECKED_SECONDS = "services.blocklist.addons.checked";
const PREF_BLOCKLIST_PLUGINS_COLLECTION = "services.blocklist.plugins.collection";
const PREF_BLOCKLIST_PLUGINS_CHECKED_SECONDS = "services.blocklist.plugins.checked";
@@ -102,21 +109,23 @@ function kintoClient() {
};
return new Kinto(config);
}
class BlocklistClient {
- constructor(collectionName, lastCheckTimePref, processCallback, signerName) {
+ constructor(collectionName, lastCheckTimePref, processCallback, signerName,
+ failureBucket) {
this.collectionName = collectionName;
this.lastCheckTimePref = lastCheckTimePref;
this.processCallback = processCallback;
this.signerName = signerName;
+ this.failureBucket = failureBucket;
}
validateCollectionSignature(payload, collection, ignoreLocal) {
return Task.spawn((function* () {
// this is a content-signature field from an autograph response.
const {x5u, signature} = yield fetchCollectionMetadata(collection);
const certChain = yield fetch(x5u).then((res) => res.text());
@@ -141,16 +150,19 @@ class BlocklistClient {
const serialized = CanonicalJSON.stringify(toSerialize);
if (verifier.verifyContentSignature(serialized, "p384ecdsa=" + signature,
certChain,
this.signerName)) {
// In case the hash is valid, apply the changes locally.
return payload;
}
+ Services.telemetry
+ .getHistogramById("SERVICES_SETTINGS_SUCCESS")
+ .add(SERVICES_SETTINGS_SYNC_SIG_FAIL);
throw new Error(INVALID_SIGNATURE);
}).bind(this));
}
/**
* Synchronize from Kinto server, if necessary.
*
* @param {int} lastModified the lastModified date (on the server) for
@@ -193,17 +205,24 @@ class BlocklistClient {
}
} catch (e) {
if (e.message == INVALID_SIGNATURE) {
// 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.
let payload = yield fetchRemoteCollection(collection);
- yield this.validateCollectionSignature(payload, collection, true);
+ try {
+ yield this.validateCollectionSignature(payload, collection, true);
+ } catch (e) {
+ Services.telemetry
+ .getHistogramById("SERVICES_SETTINGS_SUCCESS")
+ .add(SERVICES_SETTINGS_SYNC_RETRY_SIG_FAIL);
+ throw(e);
+ }
// if the signature is good (we haven't thrown), and the remote
// last_modified is newer than the local last_modified, replace the
// local data
if (payload.last_modified >= collection.lastModified) {
yield collection.clear();
yield collection.loadDump(payload.data);
}
} else {
@@ -212,16 +231,21 @@ class BlocklistClient {
}
// Read local collection of records.
let list = yield collection.list();
yield this.processCallback(list.data);
// Track last update.
this.updateLastCheck(serverTime);
+ } catch(e) {
+ Services.telemetry
+ .getHistogramById("SERVICES_SETTINGS_SUCCESS")
+ .add(this.failureBucket);
+ throw e;
} finally {
collection.db.close();
}
}).bind(this));
}
/**
* Save last time server was checked in users prefs.
@@ -282,28 +306,36 @@ function* updateJSONBlocklist(filename,
}
}
this.OneCRLBlocklistClient = new BlocklistClient(
Services.prefs.getCharPref(PREF_BLOCKLIST_ONECRL_COLLECTION),
PREF_BLOCKLIST_ONECRL_CHECKED_SECONDS,
updateCertBlocklist,
- "onecrl.content-signature.mozilla.org"
+ "onecrl.content-signature.mozilla.org",
+ SERVICES_SETTINGS_SYNC_ONECRL_FAIL
);
this.AddonBlocklistClient = new BlocklistClient(
Services.prefs.getCharPref(PREF_BLOCKLIST_ADDONS_COLLECTION),
PREF_BLOCKLIST_ADDONS_CHECKED_SECONDS,
- updateJSONBlocklist.bind(undefined, FILENAME_ADDONS_JSON)
+ updateJSONBlocklist.bind(undefined, FILENAME_ADDONS_JSON),
+ undefined,
+ SERVICES_SETTINGS_SYNC_ADDONS_FAIL
);
this.GfxBlocklistClient = new BlocklistClient(
Services.prefs.getCharPref(PREF_BLOCKLIST_GFX_COLLECTION),
PREF_BLOCKLIST_GFX_CHECKED_SECONDS,
- updateJSONBlocklist.bind(undefined, FILENAME_GFX_JSON)
+ updateJSONBlocklist.bind(undefined, FILENAME_GFX_JSON),
+ undefined,
+ SERVICES_SETTINGS_SYNC_GFX_FAIL
);
this.PluginBlocklistClient = new BlocklistClient(
Services.prefs.getCharPref(PREF_BLOCKLIST_PLUGINS_COLLECTION),
PREF_BLOCKLIST_PLUGINS_CHECKED_SECONDS,
- updateJSONBlocklist.bind(undefined, FILENAME_PLUGINS_JSON)
+ updateJSONBlocklist.bind(undefined, FILENAME_PLUGINS_JSON),
+
+ undefined,
+ SERVICES_SETTINGS_SYNC_PLUGINS_FAIL
);
--- a/services/common/blocklist-updater.js
+++ b/services/common/blocklist-updater.js
@@ -6,16 +6,17 @@ 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_BUCKET = "services.blocklist.bucket";
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";
@@ -50,29 +51,41 @@ this.checkVersions = function() {
const headers = {};
if (Services.prefs.prefHasUserValue(PREF_BLOCKLIST_LAST_ETAG)) {
const lastEtag = Services.prefs.getCharPref(PREF_BLOCKLIST_LAST_ETAG);
if (lastEtag) {
headers["If-None-Match"] = lastEtag;
}
}
- let response = yield fetch(changesEndpoint, {headers});
+ let versionInfo;
+ let response;
+
+ try {
+ response = yield fetch(changesEndpoint, {headers});
- let versionInfo;
- // No changes since last time. Go on with empty list of changes.
- if (response.status == 304) {
- versionInfo = {data: []};
- } else {
- versionInfo = yield response.json();
+ // 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 the server is failing, the JSON response might not contain the
// expected data (e.g. error response - Bug 1259145)
- if (!versionInfo.hasOwnProperty("data")) {
+ if (!response || !versionInfo.hasOwnProperty("data")) {
+ Services.telemetry
+ .getHistogramById("SERVICES_SETTINGS_SUCCESS")
+ .add(SERVICES_SETTINGS_CHANGES_FAILED);
throw new Error("Polling for changes failed.");
}
// Record new update time and the difference between local and server time
let serverTimeMillis = Date.parse(response.headers.get("Date"));
// negative clockDifference means local time is behind server time
// by the absolute of that value in seconds (positive means it's ahead)
--- a/services/common/tests/unit/head_helpers.js
+++ b/services/common/tests/unit/head_helpers.js
@@ -165,8 +165,31 @@ function uninstallFakePAC() {
function ensureStartOverKeepsIdentity() {
Cu.import("resource://gre/modules/Services.jsm");
Services.prefs.setBoolPref("services.sync-testing.startOverKeepIdentity", true);
do_register_cleanup(function() {
Services.prefs.clearUserPref("services.sync-testing.startOverKeepIdentity");
});
}
ensureStartOverKeepsIdentity();
+
+function getHistogramSnapshot(histogramName) {
+ return Cc["@mozilla.org/base/telemetry;1"]
+ .getService(Ci.nsITelemetry)
+ .getHistogramById(histogramName)
+ .snapshot();
+}
+
+function getDefaultIncrements(snapshot) {
+ let 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];
+ equal(expected, actual, `check histogram count for ${key}`);
+ }
+}
--- a/services/common/tests/unit/test_blocklist_signatures.js
+++ b/services/common/tests/unit/test_blocklist_signatures.js
@@ -10,16 +10,19 @@ const { OneCRLBlocklistClient } = Cu.imp
let server;
const PREF_BLOCKLIST_BUCKET = "services.blocklist.bucket";
const PREF_BLOCKLIST_ENFORCE_SIGNING = "services.blocklist.signing.enforced";
const PREF_BLOCKLIST_ONECRL_COLLECTION = "services.blocklist.onecrl.collection";
const PREF_SETTINGS_SERVER = "services.settings.server";
const PREF_SIGNATURE_ROOT = "security.content.signature.root_hash";
+const SERVICES_SETTINGS_SYNC_SIG_FAIL = 3;
+const SERVICES_SETTINGS_SYNC_RETRY_SIG_FAIL = 4;
+const SERVICES_SETTINGS_SYNC_ONECRL_FAIL = 5;
const CERT_DIR = "test_blocklist_signatures/";
const CHAIN_FILES =
["collection_signing_ee.pem",
"collection_signing_int.pem",
"collection_signing_root.pem"];
function getFileData(file) {
@@ -290,20 +293,29 @@ add_task(function* test_check_signatures
[RESPONSE_EMPTY_INITIAL],
"GET:/v1/buckets/blocklists/collections/certificates?":
[RESPONSE_META_EMPTY_SIG]
};
// .. and use this map to register handlers for each path
registerHandlers(emptyCollectionResponses);
+ let startHistogram = getHistogramSnapshot("SERVICES_SETTINGS_SUCCESS");
+
// With all of this set up, we attempt a sync. This will resolve if all is
// well and throw if something goes wrong.
yield OneCRLBlocklistClient.maybeSync(1000, startTime);
+ let endHistogram = getHistogramSnapshot("SERVICES_SETTINGS_SUCCESS");
+
+ // ensure that none of the services_settings_success histogram counts are
+ // affected when a succesful sync occurs
+ let expectedIncrements = getDefaultIncrements(startHistogram);
+ checkHistogramIncrements(startHistogram, endHistogram, expectedIncrements);
+
// Check that some additions (2 records) to the collection have a valid
// signature.
// This response adds two entries (RECORD1 and RECORD2) to the collection
const RESPONSE_TWO_ADDED = {
comment: "RESPONSE_TWO_ADDED",
sampleHeaders: [
"Content-Type: application/json; charset=UTF-8",
@@ -432,16 +444,25 @@ add_task(function* test_check_signatures
// checked against the valid signature - so the sync should succeed.
"GET:/v1/buckets/blocklists/collections/certificates/records?_sort=id":
[RESPONSE_COMPLETE_INITIAL_SORTED_BY_ID]
};
registerHandlers(badSigGoodSigResponses);
yield OneCRLBlocklistClient.maybeSync(5000, startTime);
+ endHistogram = getHistogramSnapshot("SERVICES_SETTINGS_SUCCESS");
+
+ // ensure that the failure count is incremented for a succesful sync with an
+ // (initial) bad signature - only SERVICES_SETTINGS_SYNC_SIG_FAIL should
+ // increment.
+ expectedIncrements = getDefaultIncrements(startHistogram);
+ expectedIncrements[SERVICES_SETTINGS_SYNC_SIG_FAIL] = 1;
+ checkHistogramIncrements(startHistogram, endHistogram, expectedIncrements);
+
const badSigGoodOldResponses = {
// In this test, we deliberately serve a bad signature initially. The
// subsequent sitnature returned is a valid one for the three item
// collection.
"GET:/v1/buckets/blocklists/collections/certificates?":
[RESPONSE_META_BAD_SIG, RESPONSE_META_EMPTY_SIG],
// The first collection state is the current state (since there's no update
// - but, since the signature is wrong, another request will be made)
@@ -471,23 +492,31 @@ add_task(function* test_check_signatures
"GET:/v1/buckets/blocklists/collections/certificates/records?_sort=-last_modified&_since=4000":
[RESPONSE_EMPTY_NO_UPDATE],
// The next request is for the full collection sorted by id. This will be
// checked against the valid signature - so the sync should succeed.
"GET:/v1/buckets/blocklists/collections/certificates/records?_sort=id":
[RESPONSE_COMPLETE_INITIAL_SORTED_BY_ID]
};
+ startHistogram = getHistogramSnapshot("SERVICES_SETTINGS_SUCCESS");
registerHandlers(allBadSigResponses);
try {
yield OneCRLBlocklistClient.maybeSync(6000, startTime);
do_throw("Sync should fail (the signature is intentionally bad)");
} catch (e) {
yield checkRecordCount(2);
}
+
+ // Ensure that the failure is reflected in the accumulated telemetry:
+ endHistogram = getHistogramSnapshot("SERVICES_SETTINGS_SUCCESS");
+ expectedIncrements[SERVICES_SETTINGS_SYNC_SIG_FAIL] = 2;
+ expectedIncrements[SERVICES_SETTINGS_SYNC_RETRY_SIG_FAIL] = 1;
+ expectedIncrements[SERVICES_SETTINGS_SYNC_ONECRL_FAIL] = 1;
+ checkHistogramIncrements(startHistogram, endHistogram, expectedIncrements);
});
function run_test() {
// ensure signatures are enforced
Services.prefs.setBoolPref(PREF_BLOCKLIST_ENFORCE_SIGNING, true);
// get a signature verifier to ensure nsNSSComponent is initialized
Cc["@mozilla.org/security/contentsignatureverifier;1"]
--- a/services/common/tests/unit/test_blocklist_updater.js
+++ b/services/common/tests/unit/test_blocklist_updater.js
@@ -2,16 +2,18 @@ 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;
+
// 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) {
try {
@@ -100,27 +102,36 @@ add_task(function* test_check_maybeSync(
response.write(JSON.stringify({
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.");
// 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);
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -7986,16 +7986,24 @@
"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,
+ "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"
+ },
"LOOP_CLIENT_CALL_URL_REQUESTS_SUCCESS": {
"expires_in_version": "never",
"kind": "boolean",
"description": "Stores 1 if generating a call URL succeeded, and 0 if it failed."
},
"LOOP_CLIENT_CALL_URL_SHARED": {
"expires_in_version": "never",
"kind": "boolean",
--- a/toolkit/mozapps/extensions/nsBlocklistService.js
+++ b/toolkit/mozapps/extensions/nsBlocklistService.js
@@ -59,16 +59,18 @@ const UNKNOWN_XPCOM_ABI =
const URI_BLOCKLIST_DIALOG = "chrome://mozapps/content/extensions/blocklist.xul"
const DEFAULT_SEVERITY = 3;
const DEFAULT_LEVEL = 2;
const MAX_BLOCK_LEVEL = 3;
const SEVERITY_OUTDATED = 0;
const VULNERABILITYSTATUS_NONE = 0;
const VULNERABILITYSTATUS_UPDATE_AVAILABLE = 1;
const VULNERABILITYSTATUS_NO_UPDATE = 2;
+const SERVICES_SETTINGS_SYNC_OK = 0;
+const SERVICES_SETTINGS_SYNC_FAILED = 1;
const EXTENSION_BLOCK_FILTERS = ["id", "name", "creator", "homepageURL", "updateURL"];
var gLoggingEnabled = null;
var gBlocklistEnabled = true;
var gBlocklistLevel = DEFAULT_LEVEL;
XPCOMUtils.defineLazyServiceGetter(this, "gConsole",
@@ -629,19 +631,24 @@ Blocklist.prototype = {
if (!this._isBlocklistLoaded())
this._loadBlocklist();
// If kinto update is enabled, do the kinto update
if (gPref.getBoolPref(PREF_BLOCKLIST_UPDATE_ENABLED)) {
const updater =
Components.utils.import("resource://services-common/blocklist-updater.js",
{});
- updater.checkVersions().catch(() => {
- // Before we enable this in release, we want to collect telemetry on
- // failed kinto updates - see bug 1254099
+ updater.checkVersions().then(() => {
+ Services.telemetry
+ .getHistogramById("SERVICES_SETTINGS_SUCCESS")
+ .add(SERVICES_SETTINGS_SYNC_OK);
+ }).catch(() => {
+ Services.telemetry
+ .getHistogramById("SERVICES_SETTINGS_SUCCESS")
+ .add(SERVICES_SETTINGS_SYNC_FAILED);
});
}
},
onXMLLoad: Task.async(function*(aEvent) {
let request = aEvent.target;
try {
gCertUtils.checkCert(request.channel);