Bug 1120362 - Part 4 - Start new telemetry subsessions on local midnight. r=vladan

toolkit/components/telemetry/TelemetrySession.jsm

@@ -28,9 +28,20 @@ const IS_CONTENT_PROCESS = (function() {
 
 // When modifying the payload in incompatible ways, please bump this version number
 const PAYLOAD_VERSION = 1;
-const PING_TYPE = "main";
+const PING_TYPE_MAIN = "main";
 const RETENTION_DAYS = 14;
 
+const REASON_DAILY = "daily";
+const REASON_SAVED_SESSION = "saved-session";
+const REASON_IDLE_DAILY = "idle-daily";
+const REASON_GATHER_PAYLOAD = "gather-payload";
+const REASON_TEST_PING = "test-ping";
+
+const SEC_IN_ONE_DAY  = 24 * 60 * 60;
+const MS_IN_ONE_DAY   = SEC_IN_ONE_DAY * 1000;
+
+const MIN_SUBSESSION_LENGTH_MS = 10 * 60 * 1000;
+
 // This is the HG changeset of the Histogram.json file, used to associate
 // submitted ping data with its histogram definition (bug 832007)
 #expand const HISTOGRAMS_FILE_VERSION = "__HISTOGRAMS_FILE_VERSION__";
@@ -111,6 +122,8 @@ function generateUUID() {
  */
 let Policy = {
   now: () => new Date(),
+  setDailyTimeout: (callback, delayMs) => setTimeout(callback, delayMs),
+  clearDailyTimeout: (id) => clearTimeout(id),
 };
 
 /**
@@ -123,6 +136,34 @@ function truncateToDays(date) {
                   0, 0, 0, 0);
 }
 
+/**
+ * Date.toISOString() gives us UTC times, this gives us local times in the ISO date format.
+ * http://www.w3.org/TR/NOTE-datetime
+ */
+function toLocalTimeISOString(date) {
+  function padNumber(number, places) {
+    number = number.toString();
+    while (number.length < places) {
+      number = "0" + number;
+    }
+    return number;
+  }
+
+  let sign = (n) => n >= 0 ? "+" : "-";
+  let tzOffset = date.getTimezoneOffset();
+
+  // YYYY-MM-DDThh:mm:ss.sTZD (eg 1997-07-16T19:20:30.45+01:00)
+  return    padNumber(date.getFullYear(), 4)
+    + "-" + padNumber(date.getMonth() + 1, 2)
+    + "-" + padNumber(date.getDate(), 2)
+    + "T" + padNumber(date.getHours(), 2)
+    + ":" + padNumber(date.getMinutes(), 2)
+    + ":" + padNumber(date.getSeconds(), 2);
+    + "." + date.getMilliseconds()
+    + sign(tzOffset) + Math.abs(Math.floor(tzOffset / 60))
+    + ":" + Math.abs(tzOffset % 60);
+}
+
 /**
  * Read current process I/O counters.
  */
@@ -300,6 +341,8 @@ let Impl = {
   _childTelemetry: [],
   // Date of the last session split
   _subsessionStartDate: null,
+  // The timer used for daily collections.
+  _dailyTimerId: null,
 
   /**
    * Gets a series of simple measurements (counters). At the moment, this
@@ -558,6 +601,8 @@ let Impl = {
   getMetadata: function getMetadata(reason) {
     this._log.trace("getMetadata - Reason " + reason);
 
+    let subsessionStartDate = toLocalTimeISOString(truncateToDays(this._subsessionStartDate));
+
     let ai = Services.appinfo;
     let ret = {
       reason: reason,
@@ -570,7 +615,7 @@ let Impl = {
       revision: HISTOGRAMS_FILE_VERSION,
       asyncPluginInit: Preferences.get(PREF_ASYNC_PLUGIN_INIT, false)
 
-      subsessionStartDate: truncateToDays(this._subsessionStartDate).toISOString(),
+      subsessionStartDate: subsessionStartDate,
     };
 
     // In order to share profile data, the appName used for Metro Firefox is "Firefox",
@@ -791,11 +836,14 @@ let Impl = {
   getSessionPayload: function getSessionPayload(reason, clearSubsession) {
     this._log.trace("getSessionPayload - reason: " + reason + ", clearSubsession: " + clearSubsession);
 
-    let measurements = this.getSimpleMeasurements(reason == "saved-session");
+    let measurements = this.getSimpleMeasurements(reason == REASON_SAVED_SESSION);
     let info = !IS_CONTENT_PROCESS ? this.getMetadata(reason) : null;
     let payload = this.assemblePayloadWithMeasurements(measurements, info, reason, clearSubsession);
 
-    this._subsessionStartDate = Policy.now();
+    if (clearSubsession) {
+      this._subsessionStartDate = Policy.now();
+      this._rescheduleDailyTimer();
+    }
 
     return payload;
   },
@@ -815,7 +863,7 @@ let Impl = {
       addClientId: true,
       addEnvironment: true,
     };
-    return TelemetryPing.send(PING_TYPE, payload, options);
+    return TelemetryPing.send(PING_TYPE_MAIN, payload, options);
   },
 
   attachObservers: function attachObservers() {
@@ -899,13 +947,7 @@ let Impl = {
     }
 
     AsyncShutdown.sendTelemetry.addBlocker(
-      "TelemetrySession: shutting down",
-      function condition(){
-        this.uninstall();
-        if (Telemetry.canSend) {
-          return this.savePendingPings();
-        }
-      }.bind(this));
+      "TelemetrySession: shutting down", () => this.shutdown());
 
     Services.obs.addObserver(this, "sessionstore-windows-restored", false);
 #ifdef MOZ_WIDGET_ANDROID
@@ -928,6 +970,8 @@ let Impl = {
       this.gatherMemory();
 
       Telemetry.asyncFetchTelemetryData(function () {});
+      this._rescheduleDailyTimer();
+
       deferred.resolve();
 
     }.bind(this), testing ? TELEMETRY_TEST_DELAY : TELEMETRY_DELAY);
@@ -1007,18 +1051,18 @@ let Impl = {
 
   savePendingPings: function savePendingPings() {
     this._log.trace("savePendingPings");
-    let payload = this.getSessionPayload("saved-session", false);
+    let payload = this.getSessionPayload(REASON_SAVED_SESSION, false);
     let options = {
       retentionDays: RETENTION_DAYS,
       addClientId: true,
       addEnvironment: true,
     };
-    return TelemetryPing.savePendingPings(PING_TYPE, payload, options);
+    return TelemetryPing.savePendingPings(PING_TYPE_MAIN, payload, options);
   },
 
   testSaveHistograms: function testSaveHistograms(file) {
     this._log.trace("testSaveHistograms - Path: " + file.path);
-    let payload = this.getSessionPayload("saved-session", false);
+    let payload = this.getSessionPayload(REASON_SAVED_SESSION, false);
     let options = {
       retentionDays: RETENTION_DAYS,
       addClientId: true,
@@ -1026,7 +1070,7 @@ let Impl = {
       overwrite: true,
       filePath: file.path,
     };
-    return TelemetryPing.testSavePingToFile(PING_TYPE, payload, options);
+    return TelemetryPing.testSavePingToFile(PING_TYPE_MAIN, payload, options);
   },
 
   /**
@@ -1049,7 +1093,7 @@ let Impl = {
 
   getPayload: function getPayload(reason, clearSubsession) {
     this._log.trace("getPayload - clearSubsession: " + clearSubsession);
-    reason = reason || "gather-payload";
+    reason = reason || REASON_GATHER_PAYLOAD;
     // This function returns the current Telemetry payload to the caller.
     // We only gather startup info once.
     if (Object.keys(this._slowSQLStartup).length == 0) {
@@ -1082,9 +1126,9 @@ let Impl = {
       this._isIdleObserver = false;
     }
     if (aTest) {
-      return this.send("test-ping");
+      return this.send(REASON_TEST_PING);
     } else if (Telemetry.canSend) {
-      return this.send("idle-daily");
+      return this.send(REASON_IDLE_DAILY);
     }
   },
 
@@ -1115,7 +1159,7 @@ let Impl = {
       this.uninstall();
 
       if (Telemetry.canSend) {
-        this.sendContentProcessPing("saved-session");
+        this.sendContentProcessPing(REASON_SAVED_SESSION);
       }
       break;
     case "cycle-collector-begin":
@@ -1143,7 +1187,7 @@ let Impl = {
       gWasDebuggerAttached = debugService.isDebuggerAttached;
       this.gatherStartup();
       break;
-    case "idle-daily":
+    case REASON_IDLE_DAILY:
       // Enqueue to main-thread, otherwise components may be inited by the
       // idle-daily category and miss the gather-telemetry notification.
       Services.tm.mainThread.dispatch((function() {
@@ -1176,14 +1220,14 @@ let Impl = {
     //    it on the next backgrounding). Not deleting it is faster, so that's what we do.
     case "application-background":
       if (Telemetry.canSend) {
-        let payload = this.getSessionPayload("saved-session", false);
+        let payload = this.getSessionPayload(REASON_SAVED_SESSION, false);
         let options = {
           retentionDays: RETENTION_DAYS,
           addClientId: true,
           addEnvironment: true,
           overwrite: true,
         };
-        TelemetryPing.savePing(PING_TYPE, payload, options);
+        TelemetryPing.savePing(PING_TYPE_MAIN, payload, options);
       }
       break;
 #endif
@@ -1196,6 +1240,10 @@ let Impl = {
    *                can send pings or not, which is used for testing.
    */
   shutdown: function(testing = false) {
+    if (this._dailyTimerId) {
+      Policy.clearDailyTimeout(this._dailyTimerId);
+      this._dailyTimerId = null;
+    }
     this.uninstall();
     if (Telemetry.canSend || testing) {
       return this.savePendingPings();
@@ -1203,12 +1251,55 @@ let Impl = {
     return Promise.resolve();
   },
 
+  _rescheduleDailyTimer: function() {
+    if (this._dailyTimerId) {
+      this._log.trace("_rescheduleDailyTimer - clearing existing timeout");
+      Policy.clearDailyTimeout(this._dailyTimerId);
+    }
+
+    let now = Policy.now();
+    let midnight = truncateToDays(now).getTime() + MS_IN_ONE_DAY;
+    let msUntilCollection = midnight - now.getTime();
+    if (msUntilCollection < MIN_SUBSESSION_LENGTH_MS) {
+      msUntilCollection += MS_IN_ONE_DAY;
+    }
+
+    this._log.trace("_rescheduleDailyTimer - now: " + now
+                    + ", scheduled: " + new Date(now.getTime() + msUntilCollection));
+    this._dailyTimerId = Policy.setDailyTimeout(() => this._onDailyTimer(), msUntilCollection);
+  },
+
+  _onDailyTimer: function() {
+    if (!this._initialized) {
+      if (this._log) {
+        this._log.warn("_onDailyTimer - not initialized");
+      } else {
+        Cu.reportError("TelemetrySession._onDailyTimer - not initialized");
+      }
+      return;
+    }
+
+    this._log.trace("_onDailyTimer");
+    let payload = this.getSessionPayload(REASON_DAILY, true);
+
+    let options = {
+      retentionDays: RETENTION_DAYS,
+      addClientId: true,
+      addEnvironment: true,
+    };
+    let promise = TelemetryPing.send(PING_TYPE_MAIN, payload, options);
+
+    this._rescheduleDailyTimer();
+    // Return the promise so tests can wait on the ping submission.
+    return promise;
+  },
+
   _isClassicReason: function(reason) {
     const classicReasons = [
-      "saved-session",
-      "idle-daily",
-      "gather-payload",
-      "test-ping",
+      REASON_SAVED_SESSION,
+      REASON_IDLE_DAILY,
+      REASON_GATHER_PAYLOAD,
+      REASON_TEST_PING,
     ];
     return classicReasons.indexOf(reason) != -1;
   },

toolkit/components/telemetry/docs/main-ping.rst

@@ -34,7 +34,7 @@ Structure::
         profileSubsessionCounter: <number>, // the running no. of all subsessions for the whole profile life time
 
         sessionStartDate: <ISO date>, // daily precision
-        subsessionStartDate: <ISO date>, // daily precision
+        subsessionStartDate: <ISO date>, // daily precision, ISO date in local time
         subsessionLength: <number>, // the subsession length in seconds
       },
 

toolkit/components/telemetry/tests/unit/head.js

@@ -73,7 +73,17 @@ function createAppInfo(id, name, version, platformVersion) {
                             XULAPPINFO_CONTRACTID, XULAppInfoFactory);
 }
 
+// Fake setTimeout and clearTimeout for the daily timer in tests for controllable behavior.
+function fakeDailyTimers(set, clear) {
+  let session = Components.utils.import("resource://gre/modules/TelemetrySession.jsm");
+  session.Policy.setDailyTimeout = set;
+  session.Policy.clearDailyTimeout = clear;
+}
+
 // Set logging preferences for all the tests.
 Services.prefs.setCharPref("toolkit.telemetry.log.level", "Trace");
 Services.prefs.setBoolPref("toolkit.telemetry.log.dump", true);
 TelemetryPing.initLogging();
+
+// Avoid timers interrupting test behavior.
+fakeDailyTimers(() => {}, () => {});

toolkit/components/telemetry/tests/unit/test_TelemetrySession.js

@@ -26,7 +26,11 @@ Cu.import("resource://gre/modules/Preferences.jsm");
 Cu.import("resource://gre/modules/osfile.jsm", this);
 
 const PING_FORMAT_VERSION = 2;
-const PING_TYPE = "main";
+const PING_TYPE_MAIN = "main";
+
+const REASON_SAVED_SESSION = "saved-session";
+const REASON_TEST_PING = "test-ping";
+const REASON_DAILY = "daily";
 
 const PLATFORM_VERSION = "1.9.2";
 const APP_VERSION = "1";
@@ -51,6 +55,9 @@ const RW_OWNER = parseInt("0600", 8);
 const NUMBER_OF_THREADS_TO_LAUNCH = 30;
 let gNumberOfThreadsLaunched = 0;
 
+const SEC_IN_ONE_DAY  = 24 * 60 * 60;
+const MS_IN_ONE_DAY   = SEC_IN_ONE_DAY * 1000;
+
 const PREF_BRANCH = "toolkit.telemetry.";
 const PREF_ENABLED = PREF_BRANCH + "enabled";
 const PREF_FHR_UPLOAD_ENABLED = "datareporting.healthreport.uploadEnabled";
@@ -98,7 +105,11 @@ function wrapWithExceptionHandler(f) {
 
 function fakeNow(date) {
   let session = Cu.import("resource://gre/modules/TelemetrySession.jsm");
-  session.Policy.now = () => date;
+  session.Policy.now = () => new Date(date.getTime());
+}
+
+function futureDate(date, offset) {
+  return new Date(date.getTime() + offset);
 }
 
 function registerPingHandler(handler) {
@@ -500,7 +511,7 @@ add_task(function* test_simplePing() {
   let request = yield gRequestIterator.next();
   let ping = decodeRequestPayload(request);
 
-  checkPingFormat(ping, PING_TYPE, true, true);
+  checkPingFormat(ping, PING_TYPE_MAIN, true, true);
 });
 
 // Saves the current session histograms, reloads them, performs a ping
@@ -527,18 +538,18 @@ add_task(function* test_saveLoadPing() {
   let ping1 = decodeRequestPayload(request1);
   let ping2 = decodeRequestPayload(request2);
 
-  checkPingFormat(ping1, PING_TYPE, true, true);
-  checkPingFormat(ping2, PING_TYPE, true, true);
+  checkPingFormat(ping1, PING_TYPE_MAIN, true, true);
+  checkPingFormat(ping2, PING_TYPE_MAIN, true, true);
 
   // Check we have the correct two requests. Ordering is not guaranteed.
-  if (ping1.payload.info.reason === "test-ping") {
+  if (ping1.payload.info.reason === REASON_TEST_PING) {
     // Until we change MainPing according to bug 1120982, common ping payload
     // will contain another nested payload.
-    checkPayload(ping1.payload, "test-ping", 1);
-    checkPayload(ping2.payload, "saved-session", 1);
+    checkPayload(ping1.payload, REASON_TEST_PING, 1);
+    checkPayload(ping2.payload, REASON_SAVED_SESSION, 1);
   } else {
-    checkPayload(ping1.payload, "saved-session", 1);
-    checkPayload(ping2.payload, "test-ping", 1);
+    checkPayload(ping1.payload, REASON_SAVED_SESSION, 1);
+    checkPayload(ping2.payload, REASON_TEST_PING, 1);
   }
 });
 
@@ -546,6 +557,7 @@ add_task(function* test_checkSubsession() {
   let now = new Date(2020, 1, 1, 12, 0, 0);
   let expectedDate = new Date(2020, 1, 1, 0, 0, 0);
   fakeNow(now);
+  TelemetrySession.setup();
 
   const COUNT_ID = "TELEMETRY_TEST_COUNT";
   const KEYED_ID = "TELEMETRY_TEST_KEYED_COUNT";
@@ -681,8 +693,10 @@ add_task(function* test_checkSubsession() {
   classic = TelemetrySession.getPayload();
   subsession = TelemetrySession.getPayload("environment-change", true);
 
-  Assert.equal(classic.info.subsessionStartDate, expectedDate.toISOString());
-  Assert.equal(subsession.info.subsessionStartDate, expectedDate.toISOString());
+  let subsessionStartDate = new Date(classic.info.subsessionStartDate);
+  Assert.equal(subsessionStartDate.toISOString(), expectedDate.toISOString());
+  subsessionStartDate = new Date(subsession.info.subsessionStartDate);
+  Assert.equal(subsessionStartDate.toISOString(), expectedDate.toISOString());
   checkHistograms(classic.histograms, subsession.histograms);
   checkKeyedHistograms(classic.keyedHistograms, subsession.keyedHistograms);
 
@@ -722,6 +736,94 @@ add_task(function* test_checkSubsession() {
   Assert.equal(subsession.keyedHistograms[KEYED_ID]["b"].sum, 1);
 });
 
+add_task(function* test_dailyCollection() {
+  let now = new Date(2030, 1, 1, 12, 0, 0);
+  let nowDay = new Date(2030, 1, 1, 0, 0, 0);
+  let timerCallback = null;
+  let timerDelay = null;
+
+  gRequestIterator = Iterator(new Request());
+
+  fakeNow(now);
+  fakeDailyTimers((callback, timeout) => {
+    dump("fake setDailyTimeout(" + callback + ", " + timeout + ")\n");
+    timerCallback = callback;
+    timerDelay = timeout;
+    return 1;
+  }, () => {});
+
+  // Init and check timer.
+  yield TelemetrySession.setup();
+  TelemetryPing.setServer("http://localhost:" + gHttpServer.identity.primaryPort);
+
+  Assert.ok(!!timerCallback);
+  Assert.ok(Number.isFinite(timerDelay));
+  let timerDate = futureDate(now, timerDelay);
+  let expectedDate = futureDate(nowDay, MS_IN_ONE_DAY);
+  Assert.equal(timerDate.toISOString(), expectedDate.toISOString());
+
+  // Set histograms to expected state.
+  const COUNT_ID = "TELEMETRY_TEST_COUNT";
+  const KEYED_ID = "TELEMETRY_TEST_KEYED_COUNT";
+  const count = Telemetry.getHistogramById(COUNT_ID);
+  const keyed = Telemetry.getKeyedHistogramById(KEYED_ID);
+
+  count.clear();
+  keyed.clear();
+  count.add(1);
+  keyed.add("a", 1);
+  keyed.add("b", 1);
+  keyed.add("b", 1);
+
+  // Trigger and collect daily ping.
+  yield timerCallback();
+  let request = yield gRequestIterator.next();
+  Assert.ok(!!request);
+  let ping = decodeRequestPayload(request);
+
+  Assert.equal(ping.type, PING_TYPE_MAIN);
+  Assert.equal(ping.payload.info.reason, REASON_DAILY);
+  let subsessionStartDate = new Date(ping.payload.info.subsessionStartDate);
+  Assert.equal(subsessionStartDate.toISOString(), nowDay.toISOString());
+
+  Assert.equal(ping.payload.histograms[COUNT_ID].sum, 1);
+  Assert.equal(ping.payload.keyedHistograms[KEYED_ID]["a"].sum, 1);
+  Assert.equal(ping.payload.keyedHistograms[KEYED_ID]["b"].sum, 2);
+
+  // Trigger and collect another ping. The histograms should be reset.
+  yield timerCallback();
+  request = yield gRequestIterator.next();
+  Assert.ok(!!request);
+  ping = decodeRequestPayload(request);
+
+  Assert.equal(ping.type, PING_TYPE_MAIN);
+  Assert.equal(ping.payload.info.reason, REASON_DAILY);
+  subsessionStartDate = new Date(ping.payload.info.subsessionStartDate);
+  Assert.equal(subsessionStartDate.toISOString(), nowDay.toISOString());
+
+  Assert.equal(ping.payload.histograms[COUNT_ID].sum, 0);
+  Assert.deepEqual(ping.payload.keyedHistograms[KEYED_ID], {});
+
+  // Trigger and collect another daily ping, with the histograms being set again.
+  count.add(1);
+  keyed.add("a", 1);
+  keyed.add("b", 1);
+
+  yield timerCallback();
+  request = yield gRequestIterator.next();
+  Assert.ok(!!request);
+  ping = decodeRequestPayload(request);
+
+  Assert.equal(ping.type, PING_TYPE_MAIN);
+  Assert.equal(ping.payload.info.reason, REASON_DAILY);
+  subsessionStartDate = new Date(ping.payload.info.subsessionStartDate);
+  Assert.equal(subsessionStartDate.toISOString(), nowDay.toISOString());
+
+  Assert.equal(ping.payload.histograms[COUNT_ID].sum, 1);
+  Assert.equal(ping.payload.keyedHistograms[KEYED_ID]["a"].sum, 1);
+  Assert.equal(ping.payload.keyedHistograms[KEYED_ID]["b"].sum, 1);
+});
+
 // Checks that an expired histogram file is deleted when loaded.
 add_task(function* test_runOldPingFile() {
   let histogramsFile = getSavedPingFile("old-histograms.dat");