Bug 1131544 - Change TelemetrySession.jsm to conform to the latest main ping specification. r=gfritzsche

toolkit/components/telemetry/TelemetrySession.jsm

@@ -12,11 +12,13 @@ const Cu = Components.utils;
 
 Cu.import("resource://gre/modules/debug.js", this);
 Cu.import("resource://gre/modules/Log.jsm");
+Cu.import("resource://gre/modules/osfile.jsm", this);
 Cu.import("resource://gre/modules/Services.jsm", this);
 Cu.import("resource://gre/modules/XPCOMUtils.jsm", this);
 Cu.import("resource://gre/modules/Promise.jsm", this);
 Cu.import("resource://gre/modules/DeferredTask.jsm", this);
 Cu.import("resource://gre/modules/Preferences.jsm");
+Cu.import("resource://gre/modules/Task.jsm");
 Cu.import("resource://gre/modules/Timer.jsm");
 
 const IS_CONTENT_PROCESS = (function() {
@@ -27,7 +29,7 @@ const IS_CONTENT_PROCESS = (function() {
 })();
 
 // When modifying the payload in incompatible ways, please bump this version number
-const PAYLOAD_VERSION = 1;
+const PAYLOAD_VERSION = 4;
 const PING_TYPE_MAIN = "main";
 const RETENTION_DAYS = 14;
 
@@ -62,6 +64,8 @@ const PREF_ASYNC_PLUGIN_INIT = "dom.ipc.plugins.asyncInit";
 
 const MESSAGE_TELEMETRY_PAYLOAD = "Telemetry:Payload";
 
+const SESSION_STATE_FILE_NAME = "session-state.json";
+
 // Do not gather data more than once a minute
 const TELEMETRY_INTERVAL = 60000;
 // Delay before intializing telemetry (ms)
@@ -115,6 +119,8 @@ XPCOMUtils.defineLazyModuleGetter(this, "UpdateChannel",
                                   "resource://gre/modules/UpdateChannel.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "TelemetryEnvironment",
                                   "resource://gre/modules/TelemetryEnvironment.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "CommonUtils",
+                                  "resource://services-common/utils.js");
 
 function generateUUID() {
   let str = Cc["@mozilla.org/uuid-generator;1"].getService(Ci.nsIUUIDGenerator).generateUUID().toString();
@@ -216,6 +222,95 @@ let processInfo = {
   }
 };
 
+/**
+ * This object allows the serialisation of asynchronous tasks. This is particularly
+ * useful to serialise write access to the disk in order to prevent race conditions
+ * to corrupt the data being written.
+ * We are using this to synchronize saving to the file that TelemetrySession persists
+ * its state in.
+ */
+let gStateSaveSerializer = {
+  _queuedOperations: [],
+  _queuedInProgress: false,
+  _log: Log.repository.getLoggerWithMessagePrefix(LOGGER_NAME, LOGGER_PREFIX),
+
+  /**
+   * Enqueues an operation to a list to serialise their execution in order to prevent race
+   * conditions. Useful to serialise access to disk.
+   *
+   * @param {Function} aFunction The task function to enqueue. It must return a promise.
+   * @return {Promise} A promise resolved when the enqueued task completes.
+   */
+  enqueueTask: function (aFunction) {
+    let promise = new Promise((resolve, reject) =>
+      this._queuedOperations.push([aFunction, resolve, reject]));
+
+    if (this._queuedOperations.length == 1) {
+      this._popAndPerformQueuedOperation();
+    }
+    return promise;
+  },
+
+  /**
+   * Make sure to flush all the pending operations.
+   * @return {Promise} A promise resolved when all the pending operations have completed.
+   */
+  flushTasks: function () {
+    let dummyTask = () => new Promise(resolve => resolve());
+    return this.enqueueTask(dummyTask);
+  },
+
+  /**
+   * Pop a task from the queue, executes it and continue to the next one.
+   * This function recursively pops all the tasks.
+   */
+  _popAndPerformQueuedOperation: function () {
+    if (!this._queuedOperations.length || this._queuedInProgress) {
+      return;
+    }
+
+    this._log.trace("_popAndPerformQueuedOperation - Performing queued operation.");
+    let [func, resolve, reject] = this._queuedOperations.shift();
+    let promise;
+
+    try {
+      this._queuedInProgress = true;
+      promise = func();
+    } catch (ex) {
+      this._log.warn("_popAndPerformQueuedOperation - Queued operation threw during execution. ",
+                     ex);
+      this._queuedInProgress = false;
+      reject(ex);
+      this._popAndPerformQueuedOperation();
+      return;
+    }
+
+    if (!promise || typeof(promise.then) != "function") {
+      let msg = "Queued operation did not return a promise: " + func;
+      this._log.warn("_popAndPerformQueuedOperation - " + msg);
+
+      this._queuedInProgress = false;
+      reject(new Error(msg));
+      this._popAndPerformQueuedOperation();
+      return;
+    }
+
+    promise.then(result => {
+        this._log.trace("_popAndPerformQueuedOperation - Queued operation completed.");
+        this._queuedInProgress = false;
+        resolve(result);
+        this._popAndPerformQueuedOperation();
+      },
+      error => {
+        this._log.warn("_popAndPerformQueuedOperation - Failure when performing queued operation.",
+                       error);
+        this._queuedInProgress = false;
+        reject(error);
+        this._popAndPerformQueuedOperation();
+      });
+  },
+};
+
 this.EXPORTED_SYMBOLS = ["TelemetrySession"];
 
 this.TelemetrySession = Object.freeze({
@@ -277,6 +372,8 @@ this.TelemetrySession = Object.freeze({
    * Used only for testing purposes.
    */
   reset: function() {
+    Impl._subsessionCounter = 0;
+    Impl._profileSubsessionCounter = 0;
     this.uninstall();
     return this.setup();
   },
@@ -325,25 +422,33 @@ let Impl = {
   _initialized: false,
   _log: null,
   _prevValues: {},
-  // Generate a unique id once per session so the server can cope with
-  // duplicate submissions.
-  _uuid: generateUUID(),
   // Regex that matches histograms we care about during startup.
   // Keep this in sync with gen-histogram-bucket-ranges.py.
   _startupHistogramRegex: /SQLITE|HTTP|SPDY|CACHE|DNS/,
   _slowSQLStartup: {},
-  _prevSession: null,
   _hasWindowRestoredObserver: false,
   _hasXulWindowVisibleObserver: false,
   _startupIO : {},
   // The previous build ID, if this is the first run with a new build.
-  // Undefined if this is not the first run, or the previous build ID is unknown.
-  _previousBuildID: undefined,
+  // Null if this is the first run, or the previous build ID is unknown.
+  _previousBuildId: null,
   // Telemetry payloads sent by child processes.
   // Each element is in the format {source: <weak-ref>, payload: <object>},
   // where source is a weak reference to the child process,
   // and payload is the telemetry payload from that child process.
   _childTelemetry: [],
+  // Generate a unique id once per session so the server can cope with duplicate
+  // submissions, orphaning and other oddities. The id is shared across subsessions.
+  _sessionId: generateUUID(),
+  // Random subsession id.
+  _subsessionId: null,
+  // Subsession id of the previous subsession (even if it was in a different session),
+  // null on first run.
+  _previousSubsessionId: null,
+  // The running no. of subsessions since the start of the browser session
+  _subsessionCounter: 0,
+  // The running no. of all subsessions for the whole profile life time
+  _profileSubsessionCounter: 0,
   // Date of the last session split
   _subsessionStartDate: null,
   // The timer used for daily collections.
@@ -608,37 +713,39 @@ let Impl = {
   getMetadata: function getMetadata(reason) {
     this._log.trace("getMetadata - Reason " + reason);
 
+    let sessionStartDate = toLocalTimeISOString(truncateToDays(this._sessionStartDate));
     let subsessionStartDate = toLocalTimeISOString(truncateToDays(this._subsessionStartDate));
+    // Compute the subsession length in milliseconds, then convert to seconds.
+    let subsessionLength =
+      Math.floor((Policy.now() - this._subsessionStartDate.getTime()) / 1000);
 
-    let ai = Services.appinfo;
     let ret = {
       reason: reason,
-      OS: ai.OS,
-      appVersion: ai.version, // TODO: In Environment, but needed for |submissionPath|
-      appName: ai.name, // TODO: In Environment, but needed for |submissionPath|
-      appBuildID: ai.appBuildID, // TODO: In Environment, but needed for |submissionPath|
-      appUpdateChannel: UpdateChannel.get(), // TODO: In Environment, but needed for |submissionPath|
-      platformBuildID: ai.platformBuildID,
       revision: HISTOGRAMS_FILE_VERSION,
-      asyncPluginInit: Preferences.get(PREF_ASYNC_PLUGIN_INIT, false)
+      asyncPluginInit: Preferences.get(PREF_ASYNC_PLUGIN_INIT, false),
 
+      // Date.getTimezoneOffset() unintuitively returns negative values if we are ahead of
+      // UTC and vice versa (e.g. -60 for UTC+1). We invert the sign here.
+      timezoneOffset: -this._subsessionStartDate.getTimezoneOffset(),
+      previousBuildId: this._previousBuildId,
+
+      sessionId: this._sessionId,
+      subsessionId: this._subsessionId,
+      previousSubsessionId: this._previousSubsessionId,
+
+      subsessionCounter: this._subsessionCounter,
+      profileSubsessionCounter: this._profileSubsessionCounter,
+
+      sessionStartDate: sessionStartDate,
       subsessionStartDate: subsessionStartDate,
+      subsessionLength: subsessionLength,
     };
 
-    // In order to share profile data, the appName used for Metro Firefox is "Firefox",
-    // (the same as desktop Firefox). We set it to "MetroFirefox" here in order to
-    // differentiate telemetry pings sent by desktop vs. metro Firefox.
-    if(Services.metro && Services.metro.immersive) {
-      ret.appName = "MetroFirefox";
-    }
-
-    if (this._previousBuildID) {
-      ret.previousBuildID = this._previousBuildID;
-    }
-
+    // TODO: Remove this when bug 1124128 lands.
     if (this._addons)
       ret.addons = this._addons;
 
+    // TODO: Remove this when bug 1124128 lands.
     let flashVersion = this.getFlashVersion();
     if (flashVersion)
       ret.flashVersion = flashVersion;
@@ -828,11 +935,6 @@ let Impl = {
       payloadObj.slowSQLStartup = this._slowSQLStartup;
     }
 
-    let clientID = TelemetryPing.clientID;
-    if (clientID && Preferences.get(PREF_FHR_UPLOAD_ENABLED, false)) {
-      payloadObj.clientID = clientID;
-    }
-
     if (this._childTelemetry.length) {
       payloadObj.childPayloads = this.getChildPayloads();
     }
@@ -840,6 +942,17 @@ let Impl = {
     return payloadObj;
   },
 
+  /**
+   * Start a new subsession.
+   */
+  startNewSubsession: function () {
+    this._subsessionStartDate = Policy.now();
+    this._previousSubsessionId = this._subsessionId;
+    this._subsessionId = generateUUID();
+    this._subsessionCounter++;
+    this._profileSubsessionCounter++;
+  },
+
   getSessionPayload: function getSessionPayload(reason, clearSubsession) {
     this._log.trace("getSessionPayload - reason: " + reason + ", clearSubsession: " + clearSubsession);
 
@@ -847,8 +960,11 @@ let Impl = {
     let info = !IS_CONTENT_PROCESS ? this.getMetadata(reason) : null;
     let payload = this.assemblePayloadWithMeasurements(measurements, info, reason, clearSubsession);
 
-    if (clearSubsession) {
-      this._subsessionStartDate = Policy.now();
+    if (!IS_CONTENT_PROCESS && clearSubsession) {
+      this.startNewSubsession();
+      // Persist session data to disk (don't wait until it completes).
+      let sessionData = this._getSessionDataObject();
+      gStateSaveSerializer.enqueueTask(() => this._saveSessionData(sessionData));
       this._rescheduleDailyTimer();
     }
 
@@ -941,8 +1057,10 @@ let Impl = {
       return Promise.resolve();
     }
 
-    this._sessionStartDate = Policy.now();
-    this._subsessionStartDate = this._sessionStartDate;
+    this.startNewSubsession();
+    // startNewSubsession sets |_subsessionStartDate| to the current date/time. Use
+    // the very same value for |_sessionStartDate|.
+    this._sessionStartDate = this._subsessionStartDate;
 
     // Initialize some probes that are kept in their own modules
     this._thirdPartyCookies = new ThirdPartyCookieProbe();
@@ -950,12 +1068,11 @@ let Impl = {
 
     // Record old value and update build ID preference if this is the first
     // run with a new build ID.
-    let previousBuildID = Preferences.get(PREF_PREVIOUS_BUILDID, undefined);
+    let previousBuildId = Preferences.get(PREF_PREVIOUS_BUILDID, null);
     let thisBuildID = Services.appinfo.appBuildID;
-    // If there is no previousBuildID preference, this._previousBuildID remains
-    // undefined so no value is sent in the telemetry metadata.
-    if (previousBuildID != thisBuildID) {
-      this._previousBuildID = previousBuildID;
+    // If there is no previousBuildId preference, we send null to the server.
+    if (previousBuildId != thisBuildID) {
+      this._previousBuildId = previousBuildId;
       Preferences.set(PREF_PREVIOUS_BUILDID, thisBuildID);
     }
 
@@ -986,6 +1103,12 @@ let Impl = {
       try {
         this._initialized = true;
 
+        let hasLoaded = yield this._loadSessionData();
+        if (!hasLoaded) {
+          // We could not load a valid session data file. Create one.
+          yield this._saveSessionData(this._getSessionDataObject()).catch(() =>
+            this._log.error("setupChromeProcess - Could not write session data to disk."));
+        }
         this.attachObservers();
         this.gatherMemory();
 
@@ -1284,7 +1407,9 @@ let Impl = {
       };
 
       if (Telemetry.canSend || testing) {
-        return this.savePendingPings().then(reset);
+        return this.savePendingPings()
+                .then(() => gStateSaveSerializer.flushTasks())
+                .then(reset);
       }
 
       reset();
@@ -1357,6 +1482,61 @@ let Impl = {
     return promise;
   },
 
+  /**
+   * Loads session data from the session data file.
+   * @return {Promise<boolean>} A promise which is resolved with a true argument when
+   *                            loading has completed, with false otherwise.
+   */
+  _loadSessionData: Task.async(function* () {
+    let dataFile = OS.Path.join(OS.Constants.Path.profileDir, "datareporting",
+                                SESSION_STATE_FILE_NAME);
+
+    // Try to load the "profileSubsessionCounter" from the state file.
+    try {
+      let data = yield CommonUtils.readJSON(dataFile);
+      if (data &&
+          "profileSubsessionCounter" in data &&
+          typeof(data.profileSubsessionCounter) == "number" &&
+          "previousSubsessionId" in data) {
+        this._previousSubsessionId = data.previousSubsessionId;
+        // Add |_subsessionCounter| to the |_profileSubsessionCounter| to account for
+        // new subsession while loading still takes place. This will always be exactly
+        // 1 - the current subsessions.
+        this._profileSubsessionCounter = data.profileSubsessionCounter +
+                                         this._subsessionCounter;
+        return true;
+      }
+    } catch (e) {
+      this._log.info("_loadSessionData - Cannot load session data file " + dataFile, e);
+    }
+    return false;
+  }),
+
+  /**
+   * Get the session data object to serialise to disk.
+   */
+  _getSessionDataObject: function() {
+    return {
+      previousSubsessionId: this._previousSubsessionId,
+      profileSubsessionCounter: this._profileSubsessionCounter,
+    };
+  },
+
+  /**
+   * Saves session data to disk.
+   */
+  _saveSessionData: Task.async(function* (sessionData) {
+    let dataDir = OS.Path.join(OS.Constants.Path.profileDir, "datareporting");
+    yield OS.File.makeDir(dataDir);
+
+    let filePath = OS.Path.join(dataDir, SESSION_STATE_FILE_NAME);
+    try {
+      yield CommonUtils.writeJSON(sessionData, filePath);
+    } catch(e) {
+      this._log.error("_saveSessionData - Failed to write session data to " + filePath, e);
+    }
+  }),
+
   _onEnvironmentChange: function() {
     this._log.trace("_onEnvironmentChange");
     let payload = this.getSessionPayload(REASON_ENVIRONMENT_CHANGE, true);

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

@@ -23,7 +23,7 @@ Structure::
         reason: <string>, // what triggered this ping: "saved-session", "environment-change", "shutdown", ...
         revision: <string>, // the Histograms.json revision
         timezoneOffset: <number>, // time-zone offset from UTC, in minutes, for the current locale
-        previousBuildId: <string>,
+        previousBuildId: <string>, // null if this is the first run, or the previous build ID is unknown
 
         sessionId: <uuid>,  // random session id, shared by subsessions
         subsessionId: <uuid>,  // random subsession id