| author | Mathieu Leplatre <mathieu@mozilla.com> |
| Wed, 22 Mar 2017 11:27:17 +0100 | |
| changeset 362515 | 744a91bd492196e9f84aab10e1ec39fb8f1d181d |
| parent 362514 | c04e86be1952dfcfff72ff111fffd41cc36eb88d |
| child 362516 | a8c405fb767d00c09a37e71d72a625247d2776b8 |
| push id | 31982 |
| push user | kwierso@gmail.com |
| push date | Tue, 06 Jun 2017 23:18:26 +0000 |
| treeherder | mozilla-central@fd04166b7114 [default view] [failures only] |
| perfherder | [talos] [build metrics] [platform microbench] (compared to previous push) |
| reviewers | bsmedberg, glasserc, mgoodwin, rhelmer |
| bugs | 1254099 |
| milestone | 55.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
|
--- a/services/common/blocklist-clients.js +++ b/services/common/blocklist-clients.js @@ -22,16 +22,18 @@ XPCOMUtils.defineLazyModuleGetter(this, XPCOMUtils.defineLazyModuleGetter(this, "Kinto", "resource://services-common/kinto-offline-client.js"); XPCOMUtils.defineLazyModuleGetter(this, "KintoHttpClient", "resource://services-common/kinto-http-client.js"); XPCOMUtils.defineLazyModuleGetter(this, "FirefoxAdapter", "resource://services-common/kinto-storage-adapter.js"); XPCOMUtils.defineLazyModuleGetter(this, "CanonicalJSON", "resource://gre/modules/CanonicalJSON.jsm"); +XPCOMUtils.defineLazyModuleGetter(this, "UptakeTelemetry", + "resource://services-common/uptake-telemetry.js"); const KEY_APPDIR = "XCurProcD"; 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"; @@ -198,16 +200,17 @@ class BlocklistClient { hooks = { "incoming-changes": [(payload, collection) => { return this.validateCollectionSignature(remote, payload, collection); }] } } let sqliteHandle; + let reportStatus = null; try { // Synchronize remote data into a local Sqlite DB. sqliteHandle = await FirefoxAdapter.openConnection({path: KINTO_STORAGE_PATH}); const options = { hooks, adapterOptions: {sqliteHandle}, }; const collection = this._kinto.collection(this.collectionName, options); @@ -228,54 +231,92 @@ class BlocklistClient { 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 (lastModified <= collectionLastModified) { this.updateLastCheck(serverTime); + reportStatus = UptakeTelemetry.STATUS.UP_TO_DATE; return; } // Fetch changes from server. try { const {ok} = await collection.sync({remote}); if (!ok) { + // Some synchronization conflicts occured. + reportStatus = UptakeTelemetry.STATUS.CONFLICT_ERROR; throw new Error("Sync failed"); } } catch (e) { if (e.message == INVALID_SIGNATURE) { + // Signature verification failed during synchronzation. + 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. const payload = await fetchRemoteCollection(remote, collection); - await this.validateCollectionSignature(remote, payload, collection, {ignoreLocal: true}); + try { + await this.validateCollectionSignature(remote, payload, collection, {ignoreLocal: true}); + } catch (e) { + reportStatus = UptakeTelemetry.STATUS.SIGNATURE_RETRY_ERROR; + 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 const localLastModified = await collection.db.getLastModified(); if (payload.last_modified >= localLastModified) { await collection.clear(); await collection.loadDump(payload.data); } } else { + // The sync has thrown, it can be a network or a general error. + if (/NetworkError/.test(e.message)) { + reportStatus = UptakeTelemetry.STATUS.NETWORK_ERROR; + } else if (/Backoff/.test(e.message)) { + reportStatus = UptakeTelemetry.STATUS.BACKOFF; + } else { + reportStatus = UptakeTelemetry.STATUS.SYNC_ERROR; + } throw e; } } // Read local collection of records. const {data} = await collection.list(); - await this.processCallback(data); + // Handle the obtained records (ie. apply locally). + try { + await this.processCallback(data); + } catch (e) { + reportStatus = UptakeTelemetry.STATUS.APPLY_ERROR; + throw e; + } // Track last update. this.updateLastCheck(serverTime); + } catch (e) { + // No specific error was tracked, mark it as unknown. + if (reportStatus === null) { + reportStatus = UptakeTelemetry.STATUS.UNKNOWN_ERROR; + } + throw e; } finally { - await sqliteHandle.close(); + if (sqliteHandle) { + await sqliteHandle.close(); + } + // No error was reported, this is a success! + if (reportStatus === null) { + reportStatus = UptakeTelemetry.STATUS.SUCCESS; + } + // Report success/error status to Telemetry. + UptakeTelemetry.report(this.identifier, reportStatus); } } /** * Save last time server was checked in users prefs. * * @param {Date} serverTime the current date return by server. */
--- a/services/common/blocklist-updater.js +++ b/services/common/blocklist-updater.js @@ -4,111 +4,163 @@ this.EXPORTED_SYMBOLS = ["checkVersions", "addTestBlocklistClient"]; const { classes: Cc, Constructor: CC, interfaces: Ci, utils: Cu } = Components; Cu.import("resource://gre/modules/XPCOMUtils.jsm"); Cu.import("resource://gre/modules/Services.jsm"); Cu.importGlobalProperties(["fetch"]); +XPCOMUtils.defineLazyModuleGetter(this, "UptakeTelemetry", + "resource://services-common/uptake-telemetry.js"); const PREF_SETTINGS_SERVER = "services.settings.server"; const PREF_SETTINGS_SERVER_BACKOFF = "services.settings.server.backoff"; 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 update source identifier. +const TELEMETRY_HISTOGRAM_KEY = "settings-changes-monitoring"; + XPCOMUtils.defineLazyGetter(this, "gBlocklistClients", function() { const BlocklistClients = Cu.import("resource://services-common/blocklist-clients.js", {}); return { [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; } +async 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 = await 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 = await 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")); + + // Check if the server asked the clients to back off. + let backoffSeconds; + if (response.headers.has("Backoff")) { + const value = parseInt(response.headers.get("Backoff"), 10); + if (!isNaN(value)) { + backoffSeconds = value; + } + } + + return {versionInfo, currentEtag, serverTimeMillis, backoffSeconds}; +} + + // This is called by the ping mechanism. // returns a promise that rejects if something goes wrong this.checkVersions = async function() { // Check if the server backoff time is elapsed. if (Services.prefs.prefHasUserValue(PREF_SETTINGS_SERVER_BACKOFF)) { const backoffReleaseTime = Services.prefs.getCharPref(PREF_SETTINGS_SERVER_BACKOFF); const remainingMilliseconds = parseInt(backoffReleaseTime, 10) - Date.now(); if (remainingMilliseconds > 0) { + // Backoff time has not elapsed yet. + UptakeTelemetry.report(TELEMETRY_HISTOGRAM_KEY, + UptakeTelemetry.STATUS.BACKOFF); throw new Error(`Server is asking clients to back off; retry in ${Math.ceil(remainingMilliseconds / 1000)}s.`); } else { Services.prefs.clearUserPref(PREF_SETTINGS_SERVER_BACKOFF); } } - // 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); } - const response = await fetch(changesEndpoint, {headers}); - - // Check if the server asked the clients to back off. - if (response.headers.has("Backoff")) { - const backoffSeconds = parseInt(response.headers.get("Backoff"), 10); - if (!isNaN(backoffSeconds)) { - const backoffReleaseTime = Date.now() + backoffSeconds * 1000; - Services.prefs.setCharPref(PREF_SETTINGS_SERVER_BACKOFF, backoffReleaseTime); + let pollResult; + try { + pollResult = await pollChanges(changesEndpoint, lastEtag); + } catch (e) { + // Report polling error to Uptake Telemetry. + let report; + if (/Server/.test(e.message)) { + report = UptakeTelemetry.STATUS.SERVER_ERROR; + } else if (/NetworkError/.test(e.message)) { + report = UptakeTelemetry.STATUS.NETWORK_ERROR; + } else { + report = UptakeTelemetry.STATUS.UNKNOWN_ERROR; } + UptakeTelemetry.report(TELEMETRY_HISTOGRAM_KEY, report); + // No need to go further. + throw new Error(`Polling for changes failed: ${e.message}.`); } - let versionInfo; - // No changes since last time. Go on with empty list of changes. - if (response.status == 304) { - versionInfo = {data: []}; - } else { - versionInfo = await response.json(); + const {serverTimeMillis, versionInfo, currentEtag, backoffSeconds} = pollResult; + + // Report polling success to Uptake Telemetry. + const report = versionInfo.length == 0 ? UptakeTelemetry.STATUS.UP_TO_DATE + : UptakeTelemetry.STATUS.SUCCESS; + UptakeTelemetry.report(TELEMETRY_HISTOGRAM_KEY, report); + + // Check if the server asked the clients to back off (for next poll). + if (backoffSeconds) { + const backoffReleaseTime = Date.now() + backoffSeconds * 1000; + Services.prefs.setCharPref(PREF_SETTINGS_SERVER_BACKOFF, backoffReleaseTime); } - // If the server is failing, the JSON response might not contain the - // expected data (e.g. error response - Bug 1259145) - if (!versionInfo.hasOwnProperty("data")) { - throw new Error("Polling for changes failed."); - } - - // 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 { await client.maybeSync(lastModified, serverTimeMillis); } catch (e) { if (!firstError) { firstError = e; @@ -117,13 +169,12 @@ this.checkVersions = async 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/moz.build +++ b/services/common/moz.build @@ -18,16 +18,17 @@ EXTRA_JS_MODULES['services-common'] += [ 'blocklist-clients.js', 'blocklist-updater.js', 'kinto-http-client.js', 'kinto-offline-client.js', 'kinto-storage-adapter.js', 'logmanager.js', 'observers.js', 'rest.js', + 'uptake-telemetry.js', 'utils.js', ] if CONFIG['MOZ_WIDGET_TOOLKIT'] != 'android': EXTRA_JS_MODULES['services-common'] += [ 'hawkclient.js', 'hawkrequest.js', 'tokenserverclient.js',
--- a/services/common/tests/unit/head_helpers.js +++ b/services/common/tests/unit/head_helpers.js @@ -154,8 +154,27 @@ function installFakePAC() { fakePACCID = MockRegistrar.register("@mozilla.org/system-proxy-settings;1", PACSystemSettings); } function uninstallFakePAC() { _("Uninstalling fake PAC."); MockRegistrar.unregister(fakePACCID); } + + +function getUptakeTelemetrySnapshot(key) { + Cu.import("resource://gre/modules/Services.jsm"); + const TELEMETRY_HISTOGRAM_ID = "UPTAKE_REMOTE_CONTENT_RESULT_1"; + return Services.telemetry + .getKeyedHistogramById(TELEMETRY_HISTOGRAM_ID) + .snapshot(key); +} + +function checkUptakeTelemetry(snapshot1, snapshot2, expectedIncrements) { + const LABELS = ["up_to_date", "success", "backoff", "pref_disabled", "parse_error", "content_error", "sign_error", "sign_retry_error", "conflict_error", "sync_error", "apply_error", "server_error", "certificate_error", "download_error", "timeout_error", "network_error", "offline_error", "cleanup_error", "unknown_error", "custom_1_error", "custom_2_error", "custom_3_error", "custom_4_error", "custom_5_error"]; + for (const label of LABELS) { + const key = LABELS.indexOf(label); + const expected = expectedIncrements[label] || 0; + const actual = snapshot2.counts[key] - snapshot1.counts[key]; + equal(expected, actual, `check histogram count for ${label}`); + } +}
--- a/services/common/tests/unit/test_blocklist_clients.js +++ b/services/common/tests/unit/test_blocklist_clients.js @@ -4,16 +4,17 @@ Cu.import("resource://gre/modules/Servic Cu.import("resource://testing-common/httpd.js"); Cu.import("resource://gre/modules/Timer.jsm"); const { FileUtils } = Cu.import("resource://gre/modules/FileUtils.jsm", {}); const { OS } = Cu.import("resource://gre/modules/osfile.jsm", {}); const { Kinto } = Cu.import("resource://services-common/kinto-offline-client.js", {}); const { FirefoxAdapter } = Cu.import("resource://services-common/kinto-storage-adapter.js", {}); const BlocklistClients = Cu.import("resource://services-common/blocklist-clients.js", {}); +const { UptakeTelemetry } = Cu.import("resource://services-common/uptake-telemetry.js", {}); const BinaryInputStream = CC("@mozilla.org/binaryinputstream;1", "nsIBinaryInputStream", "setInputStream"); const kintoFilename = "kinto.sqlite"; const gBlocklistClients = [ {client: BlocklistClients.AddonBlocklistClient, testData: ["i808", "i720", "i539"]}, {client: BlocklistClients.PluginBlocklistClient, testData: ["p1044", "p32", "p28"]}, @@ -185,36 +186,112 @@ add_task(function* test_sends_reload_mes client.maybeSync(2000, Date.now() - 1000, {loadDump: false}); }); equal(received.data.filename, client.filename); } }); add_task(clear_state); -add_task(function* test_do_nothing_when_blocklist_is_up_to_date() { +add_task(function* test_telemetry_reports_up_to_date() { for (let {client} of gBlocklistClients) { yield client.maybeSync(2000, Date.now() - 1000, {loadDump: false}); const filePath = OS.Path.join(OS.Constants.Path.profileDir, client.filename); const profFile = new FileUtils.File(filePath); const fileLastModified = profFile.lastModifiedTime = profFile.lastModifiedTime - 1000; const serverTime = Date.now(); + const startHistogram = getUptakeTelemetrySnapshot(client.identifier); yield client.maybeSync(3000, serverTime); // File was not updated. equal(fileLastModified, profFile.lastModifiedTime); // Server time was updated. const after = Services.prefs.getIntPref(client.lastCheckTimePref); equal(after, Math.round(serverTime / 1000)); + // No Telemetry was sent. + const endHistogram = getUptakeTelemetrySnapshot(client.identifier); + const expectedIncrements = {[UptakeTelemetry.STATUS.UP_TO_DATE]: 1}; + checkUptakeTelemetry(startHistogram, endHistogram, expectedIncrements); + } +}); +add_task(clear_state); + +add_task(function* test_telemetry_if_sync_succeeds() { + // We test each client because Telemetry requires preleminary declarations. + for (let {client} of gBlocklistClients) { + const serverTime = Date.now(); + const startHistogram = getUptakeTelemetrySnapshot(client.identifier); + + yield client.maybeSync(2000, serverTime, {loadDump: false}); + + const endHistogram = getUptakeTelemetrySnapshot(client.identifier); + const expectedIncrements = {[UptakeTelemetry.STATUS.SUCCESS]: 1}; + checkUptakeTelemetry(startHistogram, endHistogram, expectedIncrements); } }); add_task(clear_state); +add_task(function* test_telemetry_reports_if_application_fails() { + const {client} = gBlocklistClients[0]; + const serverTime = Date.now(); + const startHistogram = getUptakeTelemetrySnapshot(client.identifier); + const backup = client.processCallback; + client.processCallback = () => { throw new Error("boom"); }; + try { + yield client.maybeSync(2000, serverTime, {loadDump: false}); + } catch (e) {} + + client.processCallback = backup; + + const endHistogram = getUptakeTelemetrySnapshot(client.identifier); + const expectedIncrements = {[UptakeTelemetry.STATUS.APPLY_ERROR]: 1}; + checkUptakeTelemetry(startHistogram, endHistogram, expectedIncrements); +}); +add_task(clear_state); + +add_task(function* test_telemetry_reports_if_sync_fails() { + const {client} = gBlocklistClients[0]; + const serverTime = Date.now(); + + const sqliteHandle = yield FirefoxAdapter.openConnection({path: kintoFilename}); + const collection = kintoCollection(client.collectionName, sqliteHandle); + yield collection.db.saveLastModified(9999); + yield sqliteHandle.close(); + + const startHistogram = getUptakeTelemetrySnapshot(client.identifier); + + try { + yield client.maybeSync(10000, serverTime); + } catch (e) {} + + const endHistogram = getUptakeTelemetrySnapshot(client.identifier); + const expectedIncrements = {[UptakeTelemetry.STATUS.SYNC_ERROR]: 1}; + checkUptakeTelemetry(startHistogram, endHistogram, expectedIncrements); +}); +add_task(clear_state); + +add_task(function* test_telemetry_reports_unknown_errors() { + const {client} = gBlocklistClients[0]; + const serverTime = Date.now(); + const backup = FirefoxAdapter.openConnection; + FirefoxAdapter.openConnection = () => { throw new Error("Internal"); }; + const startHistogram = getUptakeTelemetrySnapshot(client.identifier); + + try { + yield client.maybeSync(2000, serverTime); + } catch (e) {} + + FirefoxAdapter.openConnection = backup; + const endHistogram = getUptakeTelemetrySnapshot(client.identifier); + const expectedIncrements = {[UptakeTelemetry.STATUS.UNKNOWN_ERROR]: 1}; + checkUptakeTelemetry(startHistogram, endHistogram, expectedIncrements); +}); +add_task(clear_state); // get a response for a given request from sample data function getSampleResponse(req, port) { const responses = { "OPTIONS": { "sampleHeaders": [ "Access-Control-Allow-Headers: Content-Length,Expires,Backoff,Retry-After,Last-Modified,Total-Records,ETag,Pragma,Cache-Control,authorization,content-type,if-none-match,Alert,Next-Page", "Access-Control-Allow-Methods: GET,HEAD,OPTIONS,POST,DELETE,OPTIONS", @@ -401,14 +478,28 @@ function getSampleResponse(req, port) { "blockID": "g200", "feature": "WEBGL_MSAA", "devices": [], "id": "c3a15ba9-e0e2-421f-e399-c995e5b8d14e", "last_modified": 3500, "os": "Darwin 11", "featureStatus": "BLOCKED_DEVICE" }]}) + }, + "GET:/v1/buckets/blocklists/collections/addons/records?_sort=-last_modified&_since=9999": { + "sampleHeaders": [ + "Access-Control-Allow-Origin: *", + "Access-Control-Expose-Headers: Retry-After, Content-Length, Alert, Backoff", + "Content-Type: application/json; charset=UTF-8", + "Server: waitress", + ], + "status": {status: 503, statusText: "Service Unavailable"}, + "responseBody": JSON.stringify({ + code: 503, + errno: 999, + error: "Service Unavailable", + }) } }; return responses[`${req.method}:${req.path}?${req.queryString}`] || responses[req.method]; }
--- a/services/common/tests/unit/test_blocklist_signatures.js +++ b/services/common/tests/unit/test_blocklist_signatures.js @@ -2,25 +2,29 @@ Cu.import("resource://services-common/blocklist-updater.js"); Cu.import("resource://testing-common/httpd.js"); const { Kinto } = Cu.import("resource://services-common/kinto-offline-client.js", {}); const { FirefoxAdapter } = Cu.import("resource://services-common/kinto-storage-adapter.js", {}); const { NetUtil } = Cu.import("resource://gre/modules/NetUtil.jsm", {}); const { OneCRLBlocklistClient } = Cu.import("resource://services-common/blocklist-clients.js", {}); +const { UptakeTelemetry } = Cu.import("resource://services-common/uptake-telemetry.js", {}); 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"; +// Telemetry reports. +const TELEMETRY_HISTOGRAM_KEY = OneCRLBlocklistClient.identifier; + const kintoFilename = "kinto.sqlite"; const CERT_DIR = "test_blocklist_signatures/"; const CHAIN_FILES = ["collection_signing_ee.pem", "collection_signing_int.pem", "collection_signing_root.pem"]; @@ -296,21 +300,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 = getUptakeTelemetrySnapshot(TELEMETRY_HISTOGRAM_KEY); + // With all of this set up, we attempt a sync. This will resolve if all is // well and throw if something goes wrong. // We don't want to load initial json dumps in this test suite. yield OneCRLBlocklistClient.maybeSync(1000, startTime, {loadDump: false}); + let endHistogram = getUptakeTelemetrySnapshot(TELEMETRY_HISTOGRAM_KEY); + + // ensure that a success histogram is tracked when a succesful sync occurs. + let expectedIncrements = {[UptakeTelemetry.STATUS.SUCCESS]: 1}; + checkUptakeTelemetry(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", @@ -437,18 +449,29 @@ add_task(function* test_check_signatures [RESPONSE_COMPLETE_INITIAL], // 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] }; registerHandlers(badSigGoodSigResponses); + + startHistogram = getUptakeTelemetrySnapshot(TELEMETRY_HISTOGRAM_KEY); + yield OneCRLBlocklistClient.maybeSync(5000, startTime); + endHistogram = getUptakeTelemetrySnapshot(TELEMETRY_HISTOGRAM_KEY); + + // 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 = {[UptakeTelemetry.STATUS.SIGNATURE_ERROR]: 1}; + checkUptakeTelemetry(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) @@ -478,23 +501,29 @@ 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 = getUptakeTelemetrySnapshot(TELEMETRY_HISTOGRAM_KEY); 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 = getUptakeTelemetrySnapshot(TELEMETRY_HISTOGRAM_KEY); + expectedIncrements = {[UptakeTelemetry.STATUS.SIGNATURE_RETRY_ERROR]: 1}; + checkUptakeTelemetry(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 @@ -1,18 +1,22 @@ Cu.import("resource://testing-common/httpd.js"); +const { UptakeTelemetry } = Cu.import("resource://services-common/uptake-telemetry.js", {}); var server; const PREF_SETTINGS_SERVER = "services.settings.server"; const PREF_SETTINGS_SERVER_BACKOFF = "services.settings.server.backoff"; 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"; +// Telemetry report result. +const TELEMETRY_HISTOGRAM_KEY = "settings-changes-monitoring"; + // 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 { @@ -59,16 +63,19 @@ add_task(function* test_check_maybeSync( // for a collection called 'test-collection' updater.addTestBlocklistClient("test-collection", { bucketName: "blocklists", maybeSync(lastModified, serverTime) { do_check_eq(lastModified, 1000); do_check_eq(serverTime, 2000); } }); + + const startHistogram = getUptakeTelemetrySnapshot(TELEMETRY_HISTOGRAM_KEY); + yield updater.checkVersions(); // 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(); let clockDifference = Services.prefs.getIntPref(PREF_CLOCK_SKEW_SECONDS); @@ -97,24 +104,25 @@ 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); + // 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); // check negative clock skew times // set to a time in the future server.registerPathHandler(changesPath, handleResponse.bind(null, Date.now() + 10000)); @@ -145,16 +153,35 @@ add_task(function* test_check_maybeSync( do_check_true(/Server is asking clients to back off; retry in \d+s./.test(e.message)); } // Once backoff time has expired, polling for changes can start again. server.registerPathHandler(changesPath, handleResponse.bind(null, 2000)); Services.prefs.setCharPref(PREF_SETTINGS_SERVER_BACKOFF, `${Date.now() - 1000}`); yield updater.checkVersions(); // Backoff tracking preference was cleared. do_check_false(Services.prefs.prefHasUserValue(PREF_SETTINGS_SERVER_BACKOFF)); + + + // 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 = getUptakeTelemetrySnapshot(TELEMETRY_HISTOGRAM_KEY); + // ensure that we've accumulated the correct telemetry + const expectedIncrements = { + [UptakeTelemetry.STATUS.UP_TO_DATE]: 4, + [UptakeTelemetry.STATUS.SUCCESS]: 1, + [UptakeTelemetry.STATUS.BACKOFF]: 1, + [UptakeTelemetry.STATUS.SERVER_ERROR]: 1, + [UptakeTelemetry.STATUS.NETWORK_ERROR]: 1, + [UptakeTelemetry.STATUS.UNKNOWN_ERROR]: 0, + }; + checkUptakeTelemetry(startHistogram, endHistogram, expectedIncrements); }); function run_test() { // Set up an HTTP Server server = new HttpServer(); server.start(-1); run_next_test();
new file mode 100644 --- /dev/null +++ b/services/common/tests/unit/test_uptake_telemetry.js @@ -0,0 +1,32 @@ +const { UptakeTelemetry } = Cu.import("resource://services-common/uptake-telemetry.js", {}); + + +function run_test() { + run_next_test(); +} + +add_task(function* test_unknown_status_is_not_reported() { + const source = "update-source"; + const startHistogram = getUptakeTelemetrySnapshot(source); + + UptakeTelemetry.report(source, "unknown-status"); + + const endHistogram = getUptakeTelemetrySnapshot(source); + const expectedIncrements = {}; + checkUptakeTelemetry(startHistogram, endHistogram, expectedIncrements); +}); + +add_task(function* test_each_status_can_be_caught_in_snapshot() { + const source = "some-source"; + const startHistogram = getUptakeTelemetrySnapshot(source); + + const expectedIncrements = {}; + for (const label of Object.keys(UptakeTelemetry.STATUS)) { + const status = UptakeTelemetry.STATUS[label]; + UptakeTelemetry.report(source, status); + expectedIncrements[status] = 1; + } + + const endHistogram = getUptakeTelemetrySnapshot(source); + checkUptakeTelemetry(startHistogram, endHistogram, expectedIncrements); +});
--- a/services/common/tests/unit/xpcshell.ini +++ b/services/common/tests/unit/xpcshell.ini @@ -55,8 +55,10 @@ skip-if = os == "android" [test_tokenauthenticatedrequest.js] skip-if = os == "android" [test_tokenserverclient.js] skip-if = os == "android" [test_storage_server.js] skip-if = os == "android" + +[test_uptake_telemetry.js]
new file mode 100644 --- /dev/null +++ b/services/common/uptake-telemetry.js @@ -0,0 +1,94 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + +"use strict"; + + +this.EXPORTED_SYMBOLS = ["UptakeTelemetry"]; + +const { utils: Cu } = Components; +const { Services } = Cu.import("resource://gre/modules/Services.jsm", {}); + + +// Telemetry report results. +const TELEMETRY_HISTOGRAM_ID = "UPTAKE_REMOTE_CONTENT_RESULT_1"; + +/** + * A Telemetry helper to report uptake of remote content. + */ +class UptakeTelemetry { + + /** + * Supported uptake statuses: + * + * - `UP_TO_DATE`: Local content was already up-to-date with remote content. + * - `SUCCESS`: Local content was updated successfully. + * - `BACKOFF`: Remote server asked clients to backoff. + * - `PARSE_ERROR`: Parsing server response has failed. + * - `CONTENT_ERROR`: Server response has unexpected content. + * - `PREF_DISABLED`: Update is disabled in user preferences. + * - `SIGNATURE_ERROR`: Signature verification after diff-based sync has failed. + * - `SIGNATURE_RETRY_ERROR`: Signature verification after full fetch has failed. + * - `CONFLICT_ERROR`: Some remote changes are in conflict with local changes. + * - `SYNC_ERROR`: Synchronization of remote changes has failed. + * - `APPLY_ERROR`: Application of changes locally has failed. + * - `SERVER_ERROR`: Server failed to respond. + * - `CERTIFICATE_ERROR`: Server certificate verification has failed. + * - `DOWNLOAD_ERROR`: Data could not be fully retrieved. + * - `TIMEOUT_ERROR`: Server response has timed out. + * - `NETWORK_ERROR`: Communication with server has failed. + * - `NETWORK_OFFLINE_ERROR`: Network not available. + * - `UNKNOWN_ERROR`: Uncategorized error. + * - `CLEANUP_ERROR`: Clean-up of temporary files has failed. + * - `CUSTOM_1_ERROR`: Update source specific error #1. + * - `CUSTOM_2_ERROR`: Update source specific error #2. + * - `CUSTOM_3_ERROR`: Update source specific error #3. + * - `CUSTOM_4_ERROR`: Update source specific error #4. + * - `CUSTOM_5_ERROR`: Update source specific error #5. + * + * @type {Object} + */ + static get STATUS() { + return { + UP_TO_DATE: "up_to_date", + SUCCESS: "success", + BACKOFF: "backoff", + PREF_DISABLED: "pref_disabled", + PARSE_ERROR: "parse_error", + CONTENT_ERROR: "content_error", + SIGNATURE_ERROR: "sign_error", + SIGNATURE_RETRY_ERROR: "sign_retry_error", + CONFLICT_ERROR: "conflict_error", + SYNC_ERROR: "sync_error", + APPLY_ERROR: "apply_error", + SERVER_ERROR: "server_error", + CERTIFICATE_ERROR: "certificate_error", + DOWNLOAD_ERROR: "download_error", + TIMEOUT_ERROR: "timeout_error", + NETWORK_ERROR: "network_error", + NETWORK_OFFLINE_ERROR: "offline_error", + CLEANUP_ERROR: "cleanup_error", + UNKNOWN_ERROR: "unknown_error", + CUSTOM_1_ERROR: "custom_1_error", + CUSTOM_2_ERROR: "custom_2_error", + CUSTOM_3_ERROR: "custom_3_error", + CUSTOM_4_ERROR: "custom_4_error", + CUSTOM_5_ERROR: "custom_5_error", + }; + } + + /** + * Reports the uptake status for the specified source. + * + * @param {string} source the identifier of the update source. + * @param {string} status the uptake status. + */ + static report(source, status) { + Services.telemetry + .getKeyedHistogramById(TELEMETRY_HISTOGRAM_ID) + .add(source, status); + } +} + +this.UptakeTelemetry = UptakeTelemetry;
--- a/toolkit/components/telemetry/Histograms.json +++ b/toolkit/components/telemetry/Histograms.json @@ -5798,16 +5798,27 @@ "record_in_processes": ["main", "content"], "alert_emails": ["application-update-telemetry-alerts@mozilla.com"], "expires_in_version": "never", "kind": "enumerated", "n_values": 30, "releaseChannelCollection": "opt-out", "description": "Update: the update wizard page displayed when the UI was closed (mapped in toolkit/mozapps/update/UpdateTelemetry.jsm)" }, + "UPTAKE_REMOTE_CONTENT_RESULT_1": { + "record_in_processes": ["all"], + "expires_in_version": "never", + "kind": "categorical", + "keyed": true, + "labels": ["up_to_date", "success", "backoff", "pref_disabled", "parse_error", "content_error", "sign_error", "sign_retry_error", "conflict_error", "sync_error", "apply_error", "server_error", "certificate_error", "download_error", "timeout_error", "network_error", "offline_error", "cleanup_error", "unknown_error", "custom_1_error", "custom_2_error", "custom_3_error", "custom_4_error", "custom_5_error"], + "releaseChannelCollection": "opt-out", + "alert_emails": ["storage-team@mozilla.com"], + "bug_numbers": [1254099], + "description": "Generic histogram to track uptake of remote content like blocklists, settings or updates." + }, "UPDATE_NOTIFICATION_SHOWN": { "record_in_processes": ["main", "content"], "alert_emails": ["application-update-telemetry-alerts@mozilla.com"], "expires_in_version": "never", "kind": "categorical", "bug_numbers": [893505], "releaseChannelCollection": "opt-out", "description": "Update: the application update doorhanger type that was displayed.",
--- a/toolkit/components/telemetry/docs/collection/histograms.rst +++ b/toolkit/components/telemetry/docs/collection/histograms.rst @@ -80,16 +80,18 @@ This histogram type allows you to record Flag histograms will ignore any changes after the flag is set, so once the flag is set, it cannot be unset. ``count`` --------- *Deprecated* (please use uint :doc:`scalars`). This histogram type is used when you want to record a count of something. It only stores a single value and defaults to `0`. +.. _histogram-type-keyed: + Keyed Histograms ---------------- Keyed histograms are collections of one of the histogram types above, indexed by a string key. This is for example useful when you want to break down certain counts by a name, like how often searches happen with which search engine. Note that when you need to record for a small set of known keys, using separate plain histograms is more efficient. .. warning::
--- a/toolkit/components/telemetry/docs/collection/index.rst +++ b/toolkit/components/telemetry/docs/collection/index.rst @@ -17,27 +17,29 @@ The current data collection possibilitie * ``environment`` data records information about the system and settings a session occurs in * :doc:`events` can record richer data on individual occurences of specific actions * ``TelemetryLog`` allows collecting ordered event entries up to a limit of 1000 entries (note: this does not have supporting analysis tools) * :doc:`measuring elapsed time <measuring-time>` * :doc:`custom pings <custom-pings>` * :doc:`stack capture <stack-capture>` allow recording application call stacks * :doc:`Use counters <use-counters>` measure the usage of web platform features * :doc:`Experiment annotations <experiments>` +* :doc:`Remote content uptake <uptake>` .. toctree:: :maxdepth: 2 :titlesonly: :hidden: :glob: scalars histograms events measuring-time custom-pings stack-capture experiments + uptake * Browser Usage Telemetry ~~~~~~~~~~~~~~~~~~~~~~~ For more information, see :ref:`browserusagetelemetry`.
new file mode 100644 --- /dev/null +++ b/toolkit/components/telemetry/docs/collection/uptake.rst @@ -0,0 +1,93 @@ +================ +Uptake Telemetry +================ + +Firefox continuously pulls data from different remote sources (eg. settings, system add-ons, …). In order to have consistent insights about the *uptake rate* of these *update sources*, our clients can use a unified Telemetry helper to report their *update status*. + +The helper — described below — reports predefined update status, which eventually gives a unified way to obtain: + +* the proportion of success among clients; +* its evolution over time; +* the distribution of error causes. + +.. notes:: + + Examples of update sources: *remote settings, addons update, addons, gfx, and plugins blocklists, certificate revocation, certificate pinning, system addons delivery…* + + Examples of update status: *up-to-date, success, network error, server error, signature error, server backoff, unknown error…* + + +Usage +----- + +.. code-block:: js + + const { UptakeTelemetry } = Cu.import("resource://services-common/uptake-telemetry.js", {}); + + UptakeTelemetry.report(source, status); + +- ``source`` - a ``string`` that is an identifier for the update source (eg. ``addons-blocklist``) +- ``status`` - one of the following status constants: + - ``UptakeTelemetry.STATUS.UP_TO_DATE``: Local content was already up-to-date with remote content. + - ``UptakeTelemetry.STATUS.SUCCESS``: Local content was updated successfully. + - ``UptakeTelemetry.STATUS.BACKOFF``: Remote server asked clients to backoff. + - ``UptakeTelemetry.STATUS.PREF_DISABLED``: Update is disabled in user preferences. + - ``UptakeTelemetry.STATUS.PARSE_ERROR``: Parsing server response has failed. + - ``UptakeTelemetry.STATUS.CONTENT_ERROR``: Server response has unexpected content. + - ``UptakeTelemetry.STATUS.SIGNATURE_ERROR``: Signature verification after diff-based sync has failed. + - ``UptakeTelemetry.STATUS.SIGNATURE_RETRY_ERROR``: Signature verification after full fetch has failed. + - ``UptakeTelemetry.STATUS.CONFLICT_ERROR``: Some remote changes are in conflict with local changes. + - ``UptakeTelemetry.STATUS.SYNC_ERROR``: Synchronization of remote changes has failed. + - ``UptakeTelemetry.STATUS.APPLY_ERROR``: Application of changes locally has failed. + - ``UptakeTelemetry.STATUS.SERVER_ERROR``: Server failed to respond. + - ``UptakeTelemetry.STATUS.CERTIFICATE_ERROR``: Server certificate verification has failed. + - ``UptakeTelemetry.STATUS.DOWNLOAD_ERROR``: Data could not be fully retrieved. + - ``UptakeTelemetry.STATUS.TIMEOUT_ERROR``: Server response has timed out. + - ``UptakeTelemetry.STATUS.NETWORK_ERROR``: Communication with server has failed. + - ``UptakeTelemetry.STATUS.NETWORK_OFFLINE_ERROR``: Network not available. + - ``UptakeTelemetry.STATUS.CLEANUP_ERROR``: Clean-up of temporary files has failed. + - ``UptakeTelemetry.STATUS.UNKNOWN_ERROR``: Uncategorized error. + - ``UptakeTelemetry.STATUS.CUSTOM_1_ERROR``: Error #1 specific to this update source. + - ``UptakeTelemetry.STATUS.CUSTOM_2_ERROR``: Error #2 specific to this update source. + - ``UptakeTelemetry.STATUS.CUSTOM_3_ERROR``: Error #3 specific to this update source. + - ``UptakeTelemetry.STATUS.CUSTOM_4_ERROR``: Error #4 specific to this update source. + - ``UptakeTelemetry.STATUS.CUSTOM_5_ERROR``: Error #5 specific to this update source. + + +The data is submitted to a single :ref:`keyed histogram <histogram-type-keyed>` whose id is ``UPTAKE_REMOTE_CONTENT_RESULT_1`` and the specified update ``source`` as the key. + +Example: + +.. code-block:: js + + const UPDATE_SOURCE = "update-monitoring"; + + let status; + try { + const data = await fetch(uri); + status = UptakeTelemetry.STATUS.SUCCESS; + } catch (e) { + status = /NetworkError/.test(e) ? + UptakeTelemetry.STATUS.NETWORK_ERROR : + UptakeTelemetry.STATUS.SERVER_ERROR ; + } + UptakeTelemetry.report(UPDATE_SOURCE, status); + + +Use-cases +--------- + +The following remote data sources are already using this unified histogram. + +* remote settings changes monitoring +* add-ons blocklist +* gfx blocklist +* plugins blocklist +* certificate revocation +* certificate pinning + +Obviously, the goal is to eventually converge and avoid ad-hoc Telemetry probes for measuring uptake of remote content. Some notable potential use-cases are: + +* nsUpdateService +* mozapps extensions update +* Shield recipe client