Bug 1523311 - Report age of Remote Settings data in Uptake telemetry r=glasserc
authorMathieu Leplatre <mathieu@mozilla.com>
Tue, 12 Mar 2019 15:13:31 +0000
changeset 521557 54058a24dab1706db37a91dc540ec006092a631e
parent 521556 4cb9ab350bcb8afdee1b27aa970e75a8577d7bd9
child 521560 648288669490287a12d7c1368d56d2b3c838fde2
push id10867
push userdvarga@mozilla.com
push dateThu, 14 Mar 2019 15:20:45 +0000
treeherdermozilla-beta@abad13547875 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersglasserc
bugs1523311
milestone67.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
Bug 1523311 - Report age of Remote Settings data in Uptake telemetry r=glasserc Report age of Remote Settings data in Uptake telemetry Differential Revision: https://phabricator.services.mozilla.com/D23135
services/common/uptake-telemetry.js
services/settings/Utils.jsm
services/settings/remote-settings.js
services/settings/test/unit/test_remote_settings_poll.js
toolkit/components/telemetry/Events.yaml
toolkit/components/telemetry/docs/collection/uptake.rst
--- a/services/common/uptake-telemetry.js
+++ b/services/common/uptake-telemetry.js
@@ -83,16 +83,17 @@ class UptakeTelemetry {
   /**
    * Reports the uptake status for the specified source.
    *
    * @param {string} component     the component reporting the uptake (eg. "normandy").
    * @param {string} status        the uptake status (eg. "network_error")
    * @param {Object} extra         extra values to report
    * @param {string} extra.source  the update source (eg. "recipe-42").
    * @param {string} extra.trigger what triggered the polling/fetching (eg. "broadcast", "timer").
+   * @param {int}    extra.age     age of pulled data in seconds
    */
   static report(component, status, extra = {}) {
     const { source } = extra;
 
     if (!source) {
       throw new Error("`source` value is mandatory.");
     }
 
--- a/services/settings/Utils.jsm
+++ b/services/settings/Utils.jsm
@@ -105,23 +105,27 @@ var Utils = {
         changes = 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;
     let serverTimeMillis = Date.parse(response.headers.get("Date"));
     // Since the response is served via a CDN, the Date header value could have been cached.
-    const ageSeconds = response.headers.has("Age") ? parseInt(response.headers.get("Age"), 10) : 0;
-    serverTimeMillis += ageSeconds * 1000;
+    const cacheAgeSeconds = response.headers.has("Age") ? parseInt(response.headers.get("Age"), 10) : 0;
+    serverTimeMillis += cacheAgeSeconds * 1000;
+
+    // Age of data (time between publication and now).
+    let lastModifiedMillis = Date.parse(response.headers.get("Last-Modified"));
+    const ageSeconds = (serverTimeMillis - lastModifiedMillis) / 1000;
 
     // 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 { changes, currentEtag, serverTimeMillis, backoffSeconds };
+    return { changes, currentEtag, serverTimeMillis, backoffSeconds, ageSeconds };
   },
 };
--- a/services/settings/remote-settings.js
+++ b/services/settings/remote-settings.js
@@ -152,17 +152,17 @@ function remoteSettingsFunction() {
    * Main polling method, called by the ping mechanism.
    *
    * @param {Object} options
 .  * @param {Object} options.expectedTimestamp (optional) The expected timestamp to be received — used by servers for cache busting.
    * @param {string} options.trigger           (optional) label to identify what triggered this sync (eg. ``"timer"``, default: `"manual"`)
    * @returns {Promise} or throws error if something goes wrong.
    */
   remoteSettings.pollChanges = async ({ expectedTimestamp, trigger = "manual" } = {}) => {
-    const telemetryArgs = {
+    let telemetryArgs = {
       source: TELEMETRY_SOURCE,
       trigger,
     };
 
     // Check if the server backoff time is elapsed.
     if (gPrefs.prefHasUserValue(PREF_SETTINGS_SERVER_BACKOFF)) {
       const backoffReleaseTime = gPrefs.getCharPref(PREF_SETTINGS_SERVER_BACKOFF);
       const remainingMilliseconds = parseInt(backoffReleaseTime, 10) - Date.now();
@@ -198,17 +198,20 @@ function remoteSettingsFunction() {
       } else {
         reportStatus = UptakeTelemetry.STATUS.UNKNOWN_ERROR;
       }
       UptakeTelemetry.report(TELEMETRY_COMPONENT, reportStatus, telemetryArgs);
       // No need to go further.
       throw new Error(`Polling for changes failed: ${e.message}.`);
     }
 
-    const {serverTimeMillis, changes, currentEtag, backoffSeconds} = pollResult;
+    const { serverTimeMillis, changes, currentEtag, backoffSeconds, ageSeconds } = pollResult;
+
+    // Report age of server data in Telemetry.
+    telemetryArgs = { age: ageSeconds, ...telemetryArgs };
 
     // Report polling success to Uptake Telemetry.
     const reportStatus = changes.length === 0 ? UptakeTelemetry.STATUS.UP_TO_DATE
                                               : UptakeTelemetry.STATUS.SUCCESS;
     UptakeTelemetry.report(TELEMETRY_COMPONENT, reportStatus, telemetryArgs);
 
     // Check if the server asked the clients to back off (for next poll).
     if (backoffSeconds) {
--- a/services/settings/test/unit/test_remote_settings_poll.js
+++ b/services/settings/test/unit/test_remote_settings_poll.js
@@ -34,19 +34,21 @@ async function clear_state() {
 }
 
 function serveChangesEntries(serverTime, entries) {
   return (request, response) => {
     response.setStatusLine(null, 200, "OK");
     response.setHeader("Content-Type", "application/json; charset=UTF-8");
     response.setHeader("Date", (new Date(serverTime)).toUTCString());
     if (entries.length) {
-      response.setHeader("ETag", `"${entries[0].last_modified}"`);
+      const latest = entries[0].last_modified;
+      response.setHeader("ETag", `"${latest}"`);
+      response.setHeader("Last-Modified", (new Date(latest)).toGMTString());
     }
-    response.write(JSON.stringify({"data": entries}));
+    response.write(JSON.stringify({ "data": entries }));
   };
 }
 
 function run_test() {
   // Set up an HTTP Server
   server = new HttpServer();
   server.start(-1);
 
@@ -279,16 +281,39 @@ add_task(async function test_client_last
 
   await RemoteSettings.pollChanges({ expectedTimestamp: '"42"' });
 
   notEqual(Services.prefs.getIntPref(c.lastCheckTimePref), 0);
 });
 add_task(clear_state);
 
 
+add_task(async function test_age_of_data_is_reported_in_uptake_status() {
+  const serverTime = 1552323900000;
+  server.registerPathHandler(CHANGES_PATH, serveChangesEntries(serverTime, [{
+    id: "b6ba7fab-a40a-4d03-a4af-6b627f3c5b36",
+    last_modified: serverTime - 3600 * 1000,
+    host: "localhost",
+    bucket: "main",
+    collection: "some-entry",
+  }]));
+  const backup = UptakeTelemetry.report;
+  let reportedAge;
+  UptakeTelemetry.report = (component, status, { age }) => {
+    reportedAge = age;
+  };
+
+  await RemoteSettings.pollChanges();
+
+  Assert.equal(reportedAge, 3600);
+  UptakeTelemetry.report = backup;
+});
+add_task(clear_state);
+
+
 add_task(async function test_success_with_partial_list() {
   function partialList(request, response) {
     const entries = [{
       id: "028261ad-16d4-40c2-a96a-66f72914d125",
       last_modified: 43,
       host: "localhost",
       bucket: "main",
       collection: "cid-1",
--- a/toolkit/components/telemetry/Events.yaml
+++ b/toolkit/components/telemetry/Events.yaml
@@ -1007,16 +1007,18 @@ uptake.remotecontent.result:
       - normandy
     extra_keys:
       source: >
         A label to distinguish what is being pulled or updated in the component (eg. recipe id,
         settings collection name, ...).
       trigger: >
         A label to distinguish what triggered the polling/fetching of remote content (eg. "broadcast",
         "timer", "forced", "manual")
+      age: >
+        The age of pulled data in seconds (ie. difference between publication time and fetch time).
     bug_numbers:
       - 1517469
     record_in_processes: ["main"]
     release_channel_collection: opt-out
     expiry_version: never
     notification_emails:
       - mleplatre@mozilla.com
       - bens-directs@mozilla.com
--- a/toolkit/components/telemetry/docs/collection/uptake.rst
+++ b/toolkit/components/telemetry/docs/collection/uptake.rst
@@ -80,20 +80,21 @@ Example:
 
 
 Additional Event Info
 '''''''''''''''''''''
 
 The Event API allows to report additional information. We support the following optional fields:
 
 - ``trigger``: A label to distinguish what triggered the polling/fetching of remote content (eg. ``"broadcast"``, ``"timer"``, ``"forced"``, ``"manual"``)
+- ``age``: The age of pulled data in seconds (ie. difference between publication time and fetch time).
 
 .. code-block:: js
 
-   UptakeTelemetry.report(component, status, { source, trigger: "timer" });
+   UptakeTelemetry.report(component, status, { source, trigger: "timer", age: 138 });
 
 
 Use-cases
 ---------
 
 The following remote data sources are already using this unified histogram.
 
 * remote settings changes monitoring