diff --git a/toolkit/components/telemetry/TelemetrySession.jsm b/toolkit/components/telemetry/TelemetrySession.jsm index 0bbc71a3c91a..7a7ecf23a6e0 100644 --- a/toolkit/components/telemetry/TelemetrySession.jsm +++ b/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: , payload: }, // 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} 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); diff --git a/toolkit/components/telemetry/docs/main-ping.rst b/toolkit/components/telemetry/docs/main-ping.rst index 516988beaa5c..14023d809e25 100644 --- a/toolkit/components/telemetry/docs/main-ping.rst +++ b/toolkit/components/telemetry/docs/main-ping.rst @@ -23,7 +23,7 @@ Structure:: reason: , // what triggered this ping: "saved-session", "environment-change", "shutdown", ... revision: , // the Histograms.json revision timezoneOffset: , // time-zone offset from UTC, in minutes, for the current locale - previousBuildId: , + previousBuildId: , // null if this is the first run, or the previous build ID is unknown sessionId: , // random session id, shared by subsessions subsessionId: , // random subsession id