diff --git a/browser/components/migration/360seProfileMigrator.js b/browser/components/migration/360seProfileMigrator.js index 1be79e11a4a4..e83f832e161b 100644 --- a/browser/components/migration/360seProfileMigrator.js +++ b/browser/components/migration/360seProfileMigrator.js @@ -8,6 +8,7 @@ const { classes: Cc, interfaces: Ci, results: Cr, utils: Cu } = Components; Cu.import("resource://gre/modules/XPCOMUtils.jsm"); Cu.import("resource://gre/modules/Services.jsm"); +Cu.import("resource://gre/modules/NetUtil.jsm"); Cu.import("resource://gre/modules/FileUtils.jsm"); Cu.import("resource://gre/modules/Task.jsm"); Cu.import("resource:///modules/MigrationUtils.jsm"); @@ -17,6 +18,45 @@ XPCOMUtils.defineLazyModuleGetter(this, "PlacesUtils", XPCOMUtils.defineLazyModuleGetter(this, "Sqlite", "resource://gre/modules/Sqlite.jsm"); +function copyToTempUTF8File(file, charset) { + let inputStream = Cc["@mozilla.org/network/file-input-stream;1"] + .createInstance(Ci.nsIFileInputStream); + inputStream.init(file, -1, -1, 0); + let inputStr = NetUtil.readInputStreamToString( + inputStream, inputStream.available(), { charset }); + + // Use random to reduce the likelihood of a name collision in createUnique. + let rand = Math.floor(Math.random() * Math.pow(2, 15)); + let leafName = "mozilla-temp-" + rand; + let tempUTF8File = FileUtils.getFile( + "TmpD", ["mozilla-temp-files", leafName], true); + tempUTF8File.createUnique(Ci.nsIFile.NORMAL_FILE_TYPE, 0o600); + + let out = FileUtils.openAtomicFileOutputStream(tempUTF8File); + try { + let bufferedOut = Cc["@mozilla.org/network/buffered-output-stream;1"] + .createInstance(Ci.nsIBufferedOutputStream); + bufferedOut.init(out, 4096); + try { + let converterOut = Cc["@mozilla.org/intl/converter-output-stream;1"] + .createInstance(Ci.nsIConverterOutputStream); + converterOut.init(bufferedOut, "utf-8", 0, 0x0000); + try { + converterOut.writeString(inputStr || ""); + bufferedOut.QueryInterface(Ci.nsISafeOutputStream).finish(); + } finally { + converterOut.close(); + } + } finally { + bufferedOut.close(); + } + } finally { + out.close(); + } + + return tempUTF8File; +} + function parseINIStrings(file) { let factory = Cc["@mozilla.org/xpcom/ini-parser-factory;1"]. getService(Ci.nsIINIParserFactory); @@ -185,7 +225,13 @@ Object.defineProperty(Qihoo360seProfileMigrator.prototype, "sourceProfiles", { if (!loginIni.isReadable()) { throw new Error("360 Secure Browser's 'login.ini' file could not be read."); } - let loginIniObj = parseINIStrings(loginIni); + + let loginIniInUtf8 = copyToTempUTF8File(loginIni, "gbk"); + let loginIniObj = parseINIStrings(loginIniInUtf8); + try { + loginIniInUtf8.remove(false); + } catch(ex) {} + let nowLoginEmail = loginIniObj.NowLogin && loginIniObj.NowLogin.email; /* diff --git a/browser/devtools/framework/toolbox.js b/browser/devtools/framework/toolbox.js index cc2c2aae74f7..101eaac8a4c0 100644 --- a/browser/devtools/framework/toolbox.js +++ b/browser/devtools/framework/toolbox.js @@ -1541,6 +1541,7 @@ Toolbox.prototype = { } if (!item) { item = this.doc.createElement("menuitem"); + item.setAttribute("type", "radio"); item.setAttribute("data-window-id", win.id); if (win.parentID) { item.setAttribute("data-parent-id", win.parentID); diff --git a/mobile/android/base/home/SearchEngineBar.java b/mobile/android/base/home/SearchEngineBar.java index 9b13db8dedd0..ff3e8dbac219 100644 --- a/mobile/android/base/home/SearchEngineBar.java +++ b/mobile/android/base/home/SearchEngineBar.java @@ -175,7 +175,8 @@ public class SearchEngineBar extends TwoWayView view = LayoutInflater.from(getContext()).inflate(R.layout.search_engine_bar_label, parent, false); } - Drawable icon = DrawableCompat.wrap(ContextCompat.getDrawable(parent.getContext(), R.drawable.search_icon_active)); + final Drawable icon = DrawableCompat.wrap( + ContextCompat.getDrawable(parent.getContext(), R.drawable.search_icon_active).mutate()); DrawableCompat.setTint(icon, getResources().getColor(R.color.disabled_grey)); final ImageView iconView = (ImageView) view.findViewById(R.id.search_engine_label); diff --git a/mobile/android/base/preferences/GeckoPreferences.java b/mobile/android/base/preferences/GeckoPreferences.java index ab23c1ccfc15..7c8578fd711a 100644 --- a/mobile/android/base/preferences/GeckoPreferences.java +++ b/mobile/android/base/preferences/GeckoPreferences.java @@ -127,9 +127,11 @@ OnSharedPreferenceChangeListener public static final String PREFS_OPEN_URLS_IN_PRIVATE = NON_PREF_PREFIX + "openExternalURLsPrivately"; public static final String PREFS_VOICE_INPUT_ENABLED = NON_PREF_PREFIX + "voice_input_enabled"; public static final String PREFS_QRCODE_ENABLED = NON_PREF_PREFIX + "qrcode_enabled"; + private static final String PREFS_DEVTOOLS = NON_PREF_PREFIX + "devtools.enabled"; private static final String ACTION_STUMBLER_UPLOAD_PREF = AppConstants.ANDROID_PACKAGE_NAME + ".STUMBLER_PREF"; + // This isn't a Gecko pref, even if it looks like one. private static final String PREFS_BROWSER_LOCALE = "locale"; @@ -692,6 +694,13 @@ OnSharedPreferenceChangeListener continue; } } + if (PREFS_DEVTOOLS.equals(key) && + RestrictedProfiles.isUserRestricted()) { + preferences.removePreference(pref); + i--; + continue; + } + setupPreferences((PreferenceGroup) pref, prefs); } else { pref.setOnPreferenceChangeListener(this); diff --git a/mobile/android/base/resources/xml-v11/preferences.xml b/mobile/android/base/resources/xml-v11/preferences.xml index 8a538df75752..4cfde7172905 100644 --- a/mobile/android/base/resources/xml-v11/preferences.xml +++ b/mobile/android/base/resources/xml-v11/preferences.xml @@ -55,7 +55,8 @@ + android:fragment="org.mozilla.gecko.preferences.GeckoPreferenceFragment" + android:key="android.not_a_preference.devtools.enabled" > diff --git a/mobile/android/base/resources/xml/preferences.xml b/mobile/android/base/resources/xml/preferences.xml index 453b1f0d78e3..bc6ab806558c 100644 --- a/mobile/android/base/resources/xml/preferences.xml +++ b/mobile/android/base/resources/xml/preferences.xml @@ -72,7 +72,8 @@ + android:summary="@string/pref_developer_remotedebugging" + android:key="android.not_a_preference.devtools.enabled" > diff --git a/toolkit/components/telemetry/Histograms.json b/toolkit/components/telemetry/Histograms.json index 4109e0e68dab..c05a8c224898 100644 --- a/toolkit/components/telemetry/Histograms.json +++ b/toolkit/components/telemetry/Histograms.json @@ -5254,6 +5254,12 @@ "n_values": 700, "description": "The Shumway feature is used during movie execution" }, + "SHUMWAY_LOAD_RESOURCE_RESULT": { + "expires_in_version": "default", + "kind": "enumerated", + "n_values": 10, + "description": "The Shumway external resource loading result" + }, "SHUMWAY_FALLBACK": { "expires_in_version": "default", "kind": "boolean", diff --git a/toolkit/components/telemetry/TelemetryController.jsm b/toolkit/components/telemetry/TelemetryController.jsm index 99e1bf49a85b..a3fbd8dec690 100644 --- a/toolkit/components/telemetry/TelemetryController.jsm +++ b/toolkit/components/telemetry/TelemetryController.jsm @@ -122,6 +122,7 @@ function configureLogging() { */ let Policy = { now: () => new Date(), + generatePingId: () => Utils.generateUUID(), } this.EXPORTED_SYMBOLS = ["TelemetryController"]; @@ -143,12 +144,7 @@ this.TelemetryController = Object.freeze({ * Used only for testing purposes. */ reset: function() { - Impl._clientID = null; - Impl._detachObservers(); - TelemetryStorage.reset(); - TelemetrySend.reset(); - - return this.setup(); + return Impl.reset(); }, /** * Used only for testing purposes. @@ -190,13 +186,14 @@ this.TelemetryController = Object.freeze({ * @param {Boolean} [aOptions.addEnvironment=false] true if the ping should contain the * environment data. * @param {Object} [aOptions.overrideEnvironment=null] set to override the environment data. - * @returns {Promise} A promise that resolves with the ping id once the ping is stored or sent. + * @returns {Promise} Test-only - a promise that resolves with the ping id once the ping is stored or sent. */ submitExternalPing: function(aType, aPayload, aOptions = {}) { aOptions.addClientId = aOptions.addClientId || false; aOptions.addEnvironment = aOptions.addEnvironment || false; - return Impl.submitExternalPing(aType, aPayload, aOptions); + const testOnly = Impl.submitExternalPing(aType, aPayload, aOptions); + return testOnly; }, /** @@ -416,7 +413,7 @@ let Impl = { // Fill the common ping fields. let pingData = { type: aType, - id: Utils.generateUUID(), + id: Policy.generatePingId(), creationDate: (Policy.now()).toISOString(), version: PING_FORMAT_VERSION, application: this._getApplicationSection(), @@ -456,7 +453,7 @@ let Impl = { * @param {Boolean} [aOptions.addEnvironment=false] true if the ping should contain the * environment data. * @param {Object} [aOptions.overrideEnvironment=null] set to override the environment data. - * @returns {Promise} A promise that is resolved with the ping id once the ping is stored or sent. + * @returns {Promise} Test-only - a promise that is resolved with the ping id once the ping is stored or sent. */ submitExternalPing: function send(aType, aPayload, aOptions) { this._log.trace("submitExternalPing - type: " + aType + ", aOptions: " + JSON.stringify(aOptions)); @@ -860,4 +857,18 @@ let Impl = { return ping; }, + + reset: Task.async(function*() { + this._clientID = null; + this._detachObservers(); + + // We need to kick of the controller setup first for tests that check the + // cached client id. + let controllerSetup = this.setupTelemetry(true); + + yield TelemetrySend.reset(); + yield TelemetryStorage.reset(); + + yield controllerSetup; + }), }; diff --git a/toolkit/components/telemetry/TelemetrySend.jsm b/toolkit/components/telemetry/TelemetrySend.jsm index b7a5e9c7523b..03e1f872317c 100644 --- a/toolkit/components/telemetry/TelemetrySend.jsm +++ b/toolkit/components/telemetry/TelemetrySend.jsm @@ -54,23 +54,38 @@ const IS_UNIFIED_TELEMETRY = Preferences.get(PREF_UNIFIED, false); const PING_FORMAT_VERSION = 4; +const MS_IN_A_MINUTE = 60 * 1000; + const PING_TYPE_DELETION = "deletion"; // We try to spread "midnight" pings out over this interval. -const MIDNIGHT_FUZZING_INTERVAL_MS = 60 * 60 * 1000; +const MIDNIGHT_FUZZING_INTERVAL_MS = 60 * MS_IN_A_MINUTE; // We delay sending "midnight" pings on this client by this interval. const MIDNIGHT_FUZZING_DELAY_MS = Math.random() * MIDNIGHT_FUZZING_INTERVAL_MS; // Timeout after which we consider a ping submission failed. -const PING_SUBMIT_TIMEOUT_MS = 2 * 60 * 1000; +const PING_SUBMIT_TIMEOUT_MS = 1.5 * MS_IN_A_MINUTE; + +// To keep resource usage in check, we limit ping sending to a maximum number +// of pings per minute. +const MAX_PING_SENDS_PER_MINUTE = 10; + +// If we have more pending pings then we can send right now, we schedule the next +// send for after SEND_TICK_DELAY. +const SEND_TICK_DELAY = 1 * MS_IN_A_MINUTE; +// If we had any ping send failures since the last ping, we use a backoff timeout +// for the next ping sends. We increase the delay exponentially up to a limit of +// SEND_MAXIMUM_BACKOFF_DELAY_MS. +// This exponential backoff will be reset by external ping submissions & idle-daily. +const SEND_MAXIMUM_BACKOFF_DELAY_MS = 120 * MS_IN_A_MINUTE; // Files that have been lying around for longer than MAX_PING_FILE_AGE are // deleted without being loaded. -const MAX_PING_FILE_AGE = 14 * 24 * 60 * 60 * 1000; // 2 weeks +const MAX_PING_FILE_AGE = 14 * 24 * 60 * MS_IN_A_MINUTE; // 2 weeks // Files that are older than OVERDUE_PING_FILE_AGE, but younger than // MAX_PING_FILE_AGE indicate that we need to send all of our pings ASAP. -const OVERDUE_PING_FILE_AGE = 7 * 24 * 60 * 60 * 1000; // 1 week +const OVERDUE_PING_FILE_AGE = 7 * 24 * 60 * MS_IN_A_MINUTE; // 1 week // Maximum number of pings to save. const MAX_LRU_PINGS = 50; @@ -83,8 +98,8 @@ const MAX_LRU_PINGS = 50; let Policy = { now: () => new Date(), midnightPingFuzzingDelay: () => MIDNIGHT_FUZZING_DELAY_MS, - setPingSendTimeout: (callback, delayMs) => setTimeout(callback, delayMs), - clearPingSendTimeout: (id) => clearTimeout(id), + setSchedulerTickTimeout: (callback, delayMs) => setTimeout(callback, delayMs), + clearSchedulerTickTimeout: (id) => clearTimeout(id), }; /** @@ -137,6 +152,7 @@ function gzipCompressString(string) { return observer.buffer; } + this.TelemetrySend = { /** * Maximum age in ms of a pending ping file before it gets evicted. @@ -159,6 +175,10 @@ this.TelemetrySend = { return MAX_LRU_PINGS; }, + get pendingPingCount() { + return TelemetrySendImpl.pendingPingCount; + }, + /** * Initializes this module. * @@ -186,7 +206,7 @@ this.TelemetrySend = { * - save the ping to disk and send it at the next opportunity * * @param {Object} ping The ping data to send, must be serializable to JSON. - * @return {Promise} A promise that is resolved when the ping is sent or saved. + * @return {Promise} Test-only - a promise that is resolved when the ping is sent or saved. */ submitPing: function(ping) { return TelemetrySendImpl.submitPing(ping); @@ -226,8 +246,253 @@ this.TelemetrySend = { testWaitOnOutgoingPings: function() { return TelemetrySendImpl.promisePendingPingActivity(); }, + + /** + * Test-only - this allows overriding behavior to enable ping sending in debug builds. + */ + setTestModeEnabled: function(testing) { + TelemetrySendImpl.setTestModeEnabled(testing); + }, }; +let CancellableTimeout = { + _deferred: null, + _timer: null, + + /** + * This waits until either the given timeout passed or the timeout was cancelled. + * + * @param {Number} timeoutMs The timeout in ms. + * @return {Promise} Promise that is resolved with false if the timeout was cancelled, + * false otherwise. + */ + promiseWaitOnTimeout: function(timeoutMs) { + if (!this._deferred) { + this._deferred = PromiseUtils.defer(); + this._timer = Policy.setSchedulerTickTimeout(() => this._onTimeout(), timeoutMs); + } + + return this._deferred.promise; + }, + + _onTimeout: function() { + if (this._deferred) { + this._deferred.resolve(false); + this._timer = null; + this._deferred = null; + } + }, + + cancelTimeout: function() { + if (this._deferred) { + Policy.clearSchedulerTickTimeout(this._timer); + this._deferred.resolve(true); + this._timer = null; + this._deferred = null; + } + }, +}; + +/** + * SendScheduler implements the timer & scheduling behavior for ping sends. + */ +let SendScheduler = { + // Whether any ping sends failed since the last tick. If yes, we start with our exponential + // backoff timeout. + _sendsFailed: false, + // The current retry delay after ping send failures. We use this for the exponential backoff, + // increasing this value everytime we had send failures since the last tick. + _backoffDelay: SEND_TICK_DELAY, + _shutdown: false, + _sendTask: null, + + _logger: null, + + get _log() { + if (!this._logger) { + this._logger = Log.repository.getLoggerWithMessagePrefix(LOGGER_NAME, LOGGER_PREFIX + "Scheduler::"); + } + + return this._logger; + }, + + shutdown: function() { + this._log.trace("shutdown"); + this._shutdown = true; + CancellableTimeout.cancelTimeout(); + return Promise.resolve(this._sendTask); + }, + + /** + * Only used for testing, resets the state to emulate a restart. + */ + reset: function() { + this._log.trace("reset"); + return this.shutdown().then(() => { + this._sendsFailed = false; + this._backoffDelay = SEND_TICK_DELAY; + this._shutdown = false; + }); + }, + + /** + * Notify the scheduler of a failure in sending out pings that warrants retrying. + * This will trigger the exponential backoff timer behavior on the next tick. + */ + notifySendsFailed: function() { + this._log.trace("notifySendsFailed"); + if (this._sendsFailed) { + return; + } + + this._sendsFailed = true; + this._log.trace("notifySendsFailed - had send failures"); + }, + + /** + * Returns whether ping submissions are currently throttled. + */ + isThrottled: function() { + const now = Policy.now(); + const nextPingSendTime = this._getNextPingSendTime(now); + return (nextPingSendTime > now.getTime()); + }, + + waitOnSendTask: function() { + return Promise.resolve(this._sendTask); + }, + + triggerSendingPings: function(immediately) { + this._log.trace("triggerSendingPings - active send task: " + !!this._sendTask + ", immediately: " + immediately); + + if (!this._sendTask) { + this._sendTask = this._doSendTask(); + let clear = () => this._sendTask = null; + this._sendTask.then(clear, clear); + } else if (immediately) { + CancellableTimeout.cancelTimeout(); + } + + return this._sendTask; + }, + + _doSendTask: Task.async(function*() { + this._backoffDelay = SEND_TICK_DELAY; + this._sendsFailed = false; + + const resetBackoffTimer = () => { + this._backoffDelay = SEND_TICK_DELAY; + }; + + for (;;) { + this._log.trace("_doSendTask iteration"); + + if (this._shutdown) { + this._log.trace("_doSendTask - shutting down, bailing out"); + return; + } + + // Get a list of pending pings, sorted by last modified, descending. + // Filter out all the pings we can't send now. This addresses scenarios like "deletion" pings + // which can be send even when upload is disabled. + let pending = TelemetryStorage.getPendingPingList(); + let current = TelemetrySendImpl.getUnpersistedPings(); + this._log.trace("_doSendTask - pending: " + pending.length + ", current: " + current.length); + pending = pending.filter(p => TelemetrySendImpl.canSend(p)); + current = current.filter(p => TelemetrySendImpl.canSend(p)); + this._log.trace("_doSendTask - can send - pending: " + pending.length + ", current: " + current.length); + + // Bail out if there is nothing to send. + if ((pending.length == 0) && (current.length == 0)) { + this._log.trace("_doSendTask - no pending pings, bailing out"); + return; + } + + // If we are currently throttled (e.g. fuzzing to avoid midnight spikes), wait for the next send window. + const now = Policy.now(); + if (this.isThrottled()) { + const nextPingSendTime = this._getNextPingSendTime(now); + this._log.trace("_doSendTask - throttled, delaying ping send to " + new Date(nextPingSendTime)); + const delay = nextPingSendTime - now.getTime(); + const cancelled = yield CancellableTimeout.promiseWaitOnTimeout(delay); + if (cancelled) { + this._log.trace("_doSendTask - throttling wait was cancelled, resetting backoff timer"); + resetBackoffTimer(); + } + + continue; + } + + let sending = pending.slice(0, MAX_PING_SENDS_PER_MINUTE); + pending = pending.slice(MAX_PING_SENDS_PER_MINUTE); + this._log.trace("_doSendTask - triggering sending of " + sending.length + " pings now" + + ", " + pending.length + " pings waiting"); + + this._sendsFailed = false; + const sendStartTime = Policy.now(); + yield TelemetrySendImpl.sendPings(current, [for (p of sending) p.id]); + if (this._shutdown || (TelemetrySend.pendingPingCount == 0)) { + this._log.trace("_doSendTask - bailing out after sending, shutdown: " + this._shutdown + + ", pendingPingCount: " + TelemetrySend.pendingPingCount); + return; + } + + // Calculate the delay before sending the next batch of pings. + // We start with a delay that makes us send max. 1 batch per minute. + // If we had send failures in the last batch, we will override this with + // a backoff delay. + const timeSinceLastSend = Policy.now() - sendStartTime; + let nextSendDelay = Math.max(0, SEND_TICK_DELAY - timeSinceLastSend); + + if (!this._sendsFailed) { + this._log.trace("_doSendTask - had no send failures, resetting backoff timer"); + resetBackoffTimer(); + } else { + const newDelay = Math.min(SEND_MAXIMUM_BACKOFF_DELAY_MS, + this._backoffDelay * 2); + this._log.trace("_doSendTask - had send failures, backing off -" + + " old timeout: " + this._backoffDelay + + ", new timeout: " + newDelay); + this._backoffDelay = newDelay; + nextSendDelay = this._backoffDelay; + } + + this._log.trace("_doSendTask - waiting for next send opportunity, timeout is " + nextSendDelay) + const cancelled = yield CancellableTimeout.promiseWaitOnTimeout(nextSendDelay); + if (cancelled) { + this._log.trace("_doSendTask - batch send wait was cancelled, resetting backoff timer"); + resetBackoffTimer(); + } + } + }), + + /** + * This helper calculates the next time that we can send pings at. + * Currently this mostly redistributes ping sends from midnight until one hour after + * to avoid submission spikes around local midnight for daily pings. + * + * @param now Date The current time. + * @return Number The next time (ms from UNIX epoch) when we can send pings. + */ + _getNextPingSendTime: function(now) { + // 1. First we check if the time is between 0am and 1am. If it's not, we send + // immediately. + // 2. If we confirmed the time is indeed between 0am and 1am in step 1, we disallow + // sending before (midnight + fuzzing delay), which is a random time between 0am-1am + // (decided at startup). + + const midnight = Utils.truncateToDays(now); + // Don't delay pings if we are not within the fuzzing interval. + if ((now.getTime() - midnight.getTime()) > MIDNIGHT_FUZZING_INTERVAL_MS) { + return now.getTime(); + } + + // Delay ping send if we are within the midnight fuzzing range. + // We spread those ping sends out between |midnight| and |midnight + midnightPingFuzzingDelay|. + return midnight.getTime() + Policy.midnightPingFuzzingDelay(); + }, + }; + let TelemetrySendImpl = { _sendingEnabled: false, _logger: null, @@ -239,11 +504,11 @@ let TelemetrySendImpl = { _pendingPingActivity: new Set(), // This is true when running in the test infrastructure. _testMode: false, + // This holds pings that we currently try and haven't persisted yet. + _currentPings: new Map(), // Count of pending pings we discarded for age on startup. _discardedPingsCount: 0, - // Count of pending pings we evicted for being over the limit on startup. - _evictedPingsCount: 0, // Count of pending pings that were overdue. _overduePingCount: 0, @@ -267,6 +532,18 @@ let TelemetrySendImpl = { return this._overduePingCount; }, + get pendingPingRequests() { + return this._pendingPingRequests; + }, + + get pendingPingCount() { + return TelemetryStorage.getPendingPingList().length + this._currentPings.size; + }, + + setTestModeEnabled: function(testing) { + this._testMode = testing; + }, + setup: Task.async(function*(testing) { this._log.trace("setup"); @@ -274,22 +551,20 @@ let TelemetrySendImpl = { this._sendingEnabled = true; this._discardedPingsCount = 0; - this._evictedPingsCount = 0; Services.obs.addObserver(this, TOPIC_IDLE_DAILY, false); this._server = Preferences.get(PREF_SERVER, undefined); - // If any pings were submitted before the delayed init finished - // we will send them now. We don't wait on sending as this could take some time. - this._sendPersistedPings(); - // Check the pending pings on disk now. - let haveOverduePings = yield this._checkPendingPings(); - if (haveOverduePings) { - // We don't wait on sending as this could take some time. - this._sendPersistedPings(); + try { + yield this._checkPendingPings(); + } catch (ex) { + this._log.error("setup - _checkPendingPings rejected", ex); } + + // Start sending pings, but don't block on this. + SendScheduler.triggerSendingPings(true); }), /** @@ -331,7 +606,7 @@ let TelemetrySendImpl = { for (let info of shouldEvict) { try { yield TelemetryStorage.removePendingPing(info.id); - ++this._evictedPingsCount; + ++evictedCount; } catch(ex) { this._log.error("_checkPendingPings - failed to evict ping", ex); } @@ -344,39 +619,40 @@ let TelemetrySendImpl = { const overduePings = infos.filter((info) => (now.getTime() - info.lastModificationDate) > OVERDUE_PING_FILE_AGE); this._overduePingCount = overduePings.length; - - if (overduePings.length > 0) { - this._log.trace("_checkForOverduePings - Have " + overduePings.length + - " overdue pending pings, ready to send " + infos.length + - " pings now."); - return true; - } - - return false; }), shutdown: Task.async(function*() { for (let topic of this.OBSERVER_TOPICS) { - Services.obs.removeObserver(this, topic); + try { + Services.obs.removeObserver(this, topic); + } catch (ex) { + this._log.error("shutdown - failed to remove observer for " + topic, ex); + } } // We can't send anymore now. this._sendingEnabled = false; - // Clear scheduled ping sends. - this._clearPingSendTimer(); // Cancel any outgoing requests. yield this._cancelOutgoingRequests(); - // ... and wait for any outstanding async ping activity. + + // Stop any active send tasks. + yield SendScheduler.shutdown(); + + // Wait for any outstanding async ping activity. yield this.promisePendingPingActivity(); + + // Save any outstanding pending pings to disk. + yield this._persistCurrentPings(); }), reset: function() { this._log.trace("reset"); + this._currentPings = new Map(); + this._overduePingCount = 0; this._discardedPingsCount = 0; - this._evictedPingsCount = 0; const histograms = [ "TELEMETRY_SUCCESS", @@ -386,53 +662,39 @@ let TelemetrySendImpl = { ]; histograms.forEach(h => Telemetry.getHistogramById(h).clear()); + + return SendScheduler.reset(); }, observe: function(subject, topic, data) { switch(topic) { case TOPIC_IDLE_DAILY: - this._sendPersistedPings(); + SendScheduler.triggerSendingPings(true); break; } }, submitPing: function(ping) { - if (!this._canSend(ping)) { + this._log.trace("submitPing - ping id: " + ping.id); + + if (!this.canSend(ping)) { this._log.trace("submitPing - Telemetry is not allowed to send pings."); return Promise.resolve(); } - // Check if we can send pings now. - const now = Policy.now(); - const nextPingSendTime = this._getNextPingSendTime(now); - const throttled = (nextPingSendTime > now.getTime()); - - // We can't send pings now, schedule a later send. - if (throttled) { - this._log.trace("submitPing - throttled, delaying ping send to " + new Date(nextPingSendTime)); - this._reschedulePingSendTimer(nextPingSendTime); - } - - if (!this._sendingEnabled || throttled) { - // Sending is disabled or throttled, add this to the pending pings. - this._log.trace("submitPing - ping is pending, sendingEnabled: " + this._sendingEnabled + - ", throttled: " + throttled); + if (!this._sendingEnabled) { + // Sending is disabled or throttled, add this to the persisted pending pings. + this._log.trace("submitPing - can't send ping now, persisting to disk - " + + "sendingEnabled: " + this._sendingEnabled); return TelemetryStorage.savePendingPing(ping); } - // Try to send the ping, persist it if sending it fails. - this._log.trace("submitPing - already initialized, ping will be sent"); - let ps = []; - ps.push(this._doPing(ping, ping.id, false) - .catch((ex) => { - this._log.info("submitPing - ping not sent, saving to disk", ex); - TelemetryStorage.savePendingPing(ping); - })); - ps.push(this._sendPersistedPings()); - - return Promise.all([for (p of ps) p.catch((ex) => { - this._log.error("submitPing - ping activity had an error", ex); - })]); + // Let the scheduler trigger sending pings if possible. + // As a safety mechanism, this resets any currently active throttling. + this._log.trace("submitPing - can send pings, trying to send now"); + this._currentPings.set(ping.id, ping); + SendScheduler.triggerSendingPings(true); + return Promise.resolve(); }, /** @@ -445,80 +707,76 @@ let TelemetrySendImpl = { _cancelOutgoingRequests: function() { // Abort any pending ping XHRs. - for (let [url, request] of this._pendingPingRequests) { - this._log.trace("_cancelOutgoingRequests - aborting ping request for " + url); + for (let [id, request] of this._pendingPingRequests) { + this._log.trace("_cancelOutgoingRequests - aborting ping request for id " + id); try { request.abort(); } catch (e) { - this._log.error("_cancelOutgoingRequests - failed to abort request to " + url, e); + this._log.error("_cancelOutgoingRequests - failed to abort request for id " + id, e); } } this._pendingPingRequests.clear(); }, - /** - * This helper calculates the next time that we can send pings at. - * Currently this mostly redistributes ping sends from midnight until one hour after - * to avoid submission spikes around local midnight for daily pings. - * - * @param now Date The current time. - * @return Number The next time (ms from UNIX epoch) when we can send pings. - */ - _getNextPingSendTime: function(now) { - // 1. First we check if the time is between 0am and 1am. If it's not, we send - // immediately. - // 2. If we confirmed the time is indeed between 0am and 1am in step 1, we disallow - // sending before (midnight + fuzzing delay), which is a random time between 0am-1am - // (decided at startup). + sendPings: function(currentPings, persistedPingIds) { + let pingSends = []; - const midnight = Utils.truncateToDays(now); - // Don't delay pings if we are not within the fuzzing interval. - if ((now.getTime() - midnight.getTime()) > MIDNIGHT_FUZZING_INTERVAL_MS) { - return now.getTime(); + for (let current of currentPings) { + let ping = current; + let p = Task.spawn(function*() { + try { + yield this._doPing(ping, ping.id, false); + } catch (ex) { + this._log.info("sendPings - ping " + ping.id + " not sent, saving to disk", ex); + yield TelemetryStorage.savePendingPing(ping); + } finally { + this._currentPings.delete(ping.id); + } + }.bind(this)); + + this._trackPendingPingTask(p); + pingSends.push(p); } - // Delay ping send if we are within the midnight fuzzing range. - // We spread those ping sends out between |midnight| and |midnight + midnightPingFuzzingDelay|. - return midnight.getTime() + Policy.midnightPingFuzzingDelay(); + if (persistedPingIds.length > 0) { + pingSends.push(this._sendPersistedPings(persistedPingIds).catch((ex) => { + this._log.info("sendPings - persisted pings not sent", ex); + })); + } + + return Promise.all(pingSends); }, /** * Send the persisted pings to the server. * + * @param {Array} List of ping ids that should be sent. + * * @return Promise A promise that is resolved when all pings finished sending or failed. */ - _sendPersistedPings: Task.async(function*() { - this._log.trace("_sendPersistedPings - Can send: " + this._canSend()); + _sendPersistedPings: Task.async(function*(pingIds) { + this._log.trace("sendPersistedPings"); if (TelemetryStorage.pendingPingCount < 1) { this._log.trace("_sendPersistedPings - no pings to send"); - return Promise.resolve(); + return; } - if (!this._canSend()) { - this._log.trace("_sendPersistedPings - Telemetry is not allowed to send pings."); - return Promise.resolve(); - } - - // Check if we can send pings now - otherwise schedule a later send. - const now = Policy.now(); - const nextPingSendTime = this._getNextPingSendTime(now); - if (nextPingSendTime > now.getTime()) { - this._log.trace("_sendPersistedPings - delaying ping send to " + new Date(nextPingSendTime)); - this._reschedulePingSendTimer(nextPingSendTime); - return Promise.resolve(); + if (pingIds.length < 1) { + this._log.trace("sendPersistedPings - no pings to send"); + return; } // We can send now. - const pendingPings = TelemetryStorage.getPendingPingList(); - this._log.trace("_sendPersistedPings - sending " + pendingPings.length + " pings"); + // If there are any send failures, _doPing() sets up handlers that e.g. trigger backoff timer behavior. + this._log.trace("sendPersistedPings - sending " + pingIds.length + " pings"); let pingSendPromises = []; - for (let ping of pendingPings) { - let p = ping; + for (let pingId of pingIds) { + const id = pingId; pingSendPromises.push( - TelemetryStorage.loadPendingPing(p.id) - .then((data) => this._doPing(data, p.id, true) - .catch(e => this._log.error("_sendPersistedPings - _doPing rejected", e)))); + TelemetryStorage.loadPendingPing(id) + .then((data) => this._doPing(data, id, true)) + .catch(e => this._log.error("sendPersistedPings - failed to send ping " + id, e))); } let promise = Promise.all(pingSendPromises); @@ -536,6 +794,11 @@ let TelemetrySendImpl = { hsuccess.add(success); hping.add(new Date() - startTime); + if (!success) { + // Let the scheduler know about send failures for triggering backoff timeouts. + SendScheduler.notifySendsFailed(); + } + if (success && isPersisted) { return TelemetryStorage.removePendingPing(id); } else { @@ -577,14 +840,15 @@ let TelemetrySendImpl = { }, _doPing: function(ping, id, isPersisted) { - if (!this._canSend(ping)) { + if (!this.canSend(ping)) { // We can't send the pings to the server, so don't try to. - this._log.trace("_doPing - Sending is disabled."); + this._log.trace("_doPing - Can't send ping " + ping.id); return Promise.resolve(); } this._log.trace("_doPing - server: " + this._server + ", persisted: " + isPersisted + ", id: " + id); + const isNewPing = isV4PingFormat(ping); const version = isNewPing ? PING_FORMAT_VERSION : 1; const url = this._server + this._getSubmissionPath(ping) + "?v=" + version; @@ -598,7 +862,7 @@ let TelemetrySendImpl = { request.overrideMimeType("text/plain"); request.setRequestHeader("Content-Type", "application/json; charset=UTF-8"); - this._pendingPingRequests.set(url, request); + this._pendingPingRequests.set(id, request); let startTime = new Date(); let deferred = PromiseUtils.defer(); @@ -612,11 +876,11 @@ let TelemetrySendImpl = { } }; - this._pendingPingRequests.delete(url); + this._pendingPingRequests.delete(id); this._onPingRequestFinished(success, startTime, id, isPersisted) .then(() => onCompletion(), (error) => { - this._log.error("_doPing - request success: " + success + ", error" + error); + this._log.error("_doPing - request success: " + success + ", error: " + error); onCompletion(); }); }; @@ -650,7 +914,7 @@ let TelemetrySendImpl = { this._log.error("_doPing - error submitting to " + url + ", status: " + status + " - server error, should retry later"); } else { - // We received an unexpected status codes. + // We received an unexpected status code. this._log.error("_doPing - error submitting to " + url + ", status: " + status + ", type: " + event.type); } @@ -688,7 +952,7 @@ let TelemetrySendImpl = { * @param {Object} [ping=null] A ping to be checked. * @return {Boolean} True if pings can be send to the servers, false otherwise. */ - _canSend: function(ping = null) { + canSend: function(ping = null) { // We only send pings from official builds, but allow overriding this for tests. if (!Telemetry.isOfficialTelemetry && !this._testMode) { return false; @@ -708,19 +972,6 @@ let TelemetrySendImpl = { return Preferences.get(PREF_TELEMETRY_ENABLED, false); }, - _reschedulePingSendTimer: function(timestamp) { - this._clearPingSendTimer(); - const interval = timestamp - Policy.now(); - this._pingSendTimer = Policy.setPingSendTimeout(() => this._sendPersistedPings(), interval); - }, - - _clearPingSendTimer: function() { - if (this._pingSendTimer) { - Policy.clearPingSendTimeout(this._pingSendTimer); - this._pingSendTimer = null; - } - }, - /** * Track any pending ping send and save tasks through the promise passed here. * This is needed to block shutdown on any outstanding ping activity. @@ -738,8 +989,32 @@ let TelemetrySendImpl = { */ promisePendingPingActivity: function () { this._log.trace("promisePendingPingActivity - Waiting for ping task"); - return Promise.all([for (p of this._pendingPingActivity) p.catch(ex => { + let p = [for (p of this._pendingPingActivity) p.catch(ex => { this._log.error("promisePendingPingActivity - ping activity had an error", ex); - })]); + })]; + p.push(SendScheduler.waitOnSendTask()); + return Promise.all(p); + }, + + _persistCurrentPings: Task.async(function*() { + for (let [id, ping] of this._currentPings) { + try { + yield TelemetryStorage.savePendingPing(ping); + this._log.trace("_persistCurrentPings - saved ping " + id); + } catch (ex) { + this._log.error("_persistCurrentPings - failed to save ping " + id, ex); + } finally { + this._currentPings.delete(id); + } + } + }), + + /** + * Returns the current pending, not yet persisted, pings, newest first. + */ + getUnpersistedPings: function() { + let current = [...this._currentPings.values()]; + current.reverse(); + return current; }, }; diff --git a/toolkit/components/telemetry/TelemetryStorage.jsm b/toolkit/components/telemetry/TelemetryStorage.jsm index 750874b72944..efc969a9c9cd 100644 --- a/toolkit/components/telemetry/TelemetryStorage.jsm +++ b/toolkit/components/telemetry/TelemetryStorage.jsm @@ -55,8 +55,6 @@ const ARCHIVE_SIZE_PROBE_SPECIAL_VALUE = 300; const UUID_REGEX = /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/i; -let isPingDirectoryCreated = false; - /** * This is a policy object used to override behavior for testing. */ @@ -909,19 +907,18 @@ let TelemetryStorageImpl = { * compression will be used. * @returns {promise} */ - savePingToFile: function(ping, filePath, overwrite, compress = false) { - return Task.spawn(function*() { - try { - let pingString = JSON.stringify(ping); - let options = { tmpPath: filePath + ".tmp", noOverwrite: !overwrite }; - if (compress) { - options.compression = "lz4"; - } - yield OS.File.writeAtomic(filePath, pingString, options); - } catch(e if e.becauseExists) { + savePingToFile: Task.async(function*(ping, filePath, overwrite, compress = false) { + try { + this._log.trace("savePingToFile - path: " + filePath); + let pingString = JSON.stringify(ping); + let options = { tmpPath: filePath + ".tmp", noOverwrite: !overwrite }; + if (compress) { + options.compression = "lz4"; } - }) - }, + yield OS.File.writeAtomic(filePath, pingString, options); + } catch(e if e.becauseExists) { + } + }), /** * Save a ping to its file. @@ -986,6 +983,7 @@ let TelemetryStorageImpl = { path: path, lastModificationDate: Policy.now().getTime(), }); + this._log.trace("savePendingPing - saved ping with id " + ping.id); }); }, @@ -1024,14 +1022,15 @@ let TelemetryStorageImpl = { return Promise.resolve(this._buildPingList()); } - // Make sure to clear the task once done. - let clear = pings => { + // Since there's no pending pings scan task running, start it. + // Also make sure to clear the task once done. + this._scanPendingPingsTask = this._scanPendingPings().then(pings => { this._scanPendingPingsTask = null; return pings; - }; - - // Since there's no pending pings scan task running, start it. - this._scanPendingPingsTask = this._scanPendingPings().then(clear, clear); + }, ex => { + this._scanPendingPingsTask = null; + throw ex; + }); return this._scanPendingPingsTask; }, @@ -1059,16 +1058,23 @@ let TelemetryStorageImpl = { return []; } - let info = yield OS.File.stat(file.path); + let info; + try { + info = yield OS.File.stat(file.path); + } catch (ex) { + this._log.error("_scanPendingPings - failed to stat file " + file.path, ex); + continue; + } + let id = OS.Path.basename(file.path); if (!UUID_REGEX.test(id)) { - this._log.trace("_scanPendingPings - unknown filename is not a UUID: " + id); + this._log.trace("_scanPendingPings - filename is not a UUID: " + id); id = Utils.generateUUID(); } this._pendingPings.set(id, { path: file.path, - lastModificationDate: info.lastModificationDate, + lastModificationDate: info.lastModificationDate.getTime(), }); } @@ -1241,9 +1247,8 @@ function getPingDirectory() { return Task.spawn(function*() { let directory = TelemetryStorage.pingDirectoryPath; - if (!isPingDirectoryCreated) { + if (!(yield OS.File.exists(directory))) { yield OS.File.makeDir(directory, { unixMode: OS.Constants.S_IRWXU }); - isPingDirectoryCreated = true; } return directory; diff --git a/toolkit/components/telemetry/docs/pings.rst b/toolkit/components/telemetry/docs/pings.rst index 3ebd8217fbaf..3ba42a4b9856 100644 --- a/toolkit/components/telemetry/docs/pings.rst +++ b/toolkit/components/telemetry/docs/pings.rst @@ -14,11 +14,23 @@ It contains some basic information shared between different ping types, the :doc Submission ========== -Pings are submitted via a common API on ``TelemetryController``. It allows callers to choose a custom retention period that determines how long pings are kept on disk if submission wasn't successful. -If a ping failed to submit (e.g. because of missing internet connection), Telemetry will retry to submit it until its retention period is up. +Pings are submitted via a common API on ``TelemetryController``. +If a ping fails to successfully submit to the server immediately (e.g. because +of missing internet connection), Telemetry will store it on disk and retry to +send it until the maximum ping age is exceeded (14 days). *Note:* the :doc:`main pings ` are kept locally even after successful submission to enable the HealthReport and SelfSupport features. They will be deleted after their retention period of 180 days. +Sending of pending pings starts as soon as the delayed startup is finished. They are sent in batches, newest-first, with up +to 10 persisted pings per batch plus all unpersisted pings. +The send logic then waits for each batch to complete. + +If it succeeds we trigger the next send of a ping batch. This is delayed as needed to only trigger one batch send per minute. + +If ping sending encounters an error that means retrying later, a backoff timeout behavior is +triggered, exponentially increasing the timeout for the next try from 1 minute up to a limit of 120 minutes. +Any new ping submissions and "idle-daily" events reset this behavior as a safety mechanism and trigger immediate ping sending. + The telemetry server team is working towards `the common services status codes `_, but for now the following logic is sufficient for Telemetry: * `2XX` - success, don't resubmit diff --git a/toolkit/components/telemetry/tests/unit/head.js b/toolkit/components/telemetry/tests/unit/head.js index e2a353d2229c..e717440af61d 100644 --- a/toolkit/components/telemetry/tests/unit/head.js +++ b/toolkit/components/telemetry/tests/unit/head.js @@ -5,6 +5,9 @@ const { classes: Cc, utils: Cu, interfaces: Ci, results: Cr } = Components; Cu.import("resource://gre/modules/TelemetryController.jsm", this); Cu.import("resource://gre/modules/Services.jsm", this); +Cu.import("resource://gre/modules/PromiseUtils.jsm", this); +Cu.import("resource://gre/modules/Task.jsm", this); +Cu.import("resource://testing-common/httpd.js", this); const gIsWindows = ("@mozilla.org/windows-registry-key;1" in Cc); const gIsMac = ("@mozilla.org/xpcom/mac-utils;1" in Cc); @@ -22,6 +25,78 @@ const UUID_REGEX = /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12 let gOldAppInfo = null; let gGlobalScope = this; +const PingServer = { + _httpServer: null, + _started: false, + _defers: [ PromiseUtils.defer() ], + _currentDeferred: 0, + + get port() { + return this._httpServer.identity.primaryPort; + }, + + get started() { + return this._started; + }, + + registerPingHandler: function(handler) { + const wrapped = wrapWithExceptionHandler(handler); + this._httpServer.registerPrefixHandler("/submit/telemetry/", wrapped); + }, + + resetPingHandler: function() { + this.registerPingHandler((request, response) => { + let deferred = this._defers[this._defers.length - 1]; + this._defers.push(PromiseUtils.defer()); + deferred.resolve(request); + }); + }, + + start: function() { + this._httpServer = new HttpServer(); + this._httpServer.start(-1); + this._started = true; + this.clearRequests(); + this.resetPingHandler(); + }, + + stop: function() { + return new Promise(resolve => { + this._httpServer.stop(resolve); + this._started = false; + }); + }, + + clearRequests: function() { + this._defers = [ PromiseUtils.defer() ]; + this._currentDeferred = 0; + }, + + promiseNextRequest: function() { + const deferred = this._defers[this._currentDeferred++]; + return deferred.promise; + }, + + promiseNextPing: function() { + return this.promiseNextRequest().then(request => decodeRequestPayload(request)); + }, + + promiseNextRequests: Task.async(function*(count) { + let results = []; + for (let i=0; i { + return [for (req of requests) decodeRequestPayload(req)]; + }); + }, +}; + /** * Decode the payload of an HTTP request into a ping. * @param {Object} request The data representing an HTTP request (nsIHttpRequest). @@ -63,6 +138,19 @@ function decodeRequestPayload(request) { return payload; } +function wrapWithExceptionHandler(f) { + function wrapper(...args) { + try { + f(...args); + } catch (ex if typeof(ex) == 'object') { + dump("Caught exception: " + ex.message + "\n"); + dump(ex.stack); + do_test_finished(); + } + } + return wrapper; +} + function loadAddonManager(id, name, version, platformVersion) { let ns = {}; Cu.import("resource://gre/modules/Services.jsm", ns); @@ -162,8 +250,9 @@ function fakeNow(...args) { // Fake the timeout functions for TelemetryController sending. function fakePingSendTimer(set, clear) { let module = Cu.import("resource://gre/modules/TelemetrySend.jsm"); - module.Policy.setPingSendTimeout = set; - module.Policy.clearPingSendTimeout = clear; + let obj = Cu.cloneInto({set, clear}, module, {cloneFunctions:true}); + module.Policy.setSchedulerTickTimeout = obj.set; + module.Policy.clearSchedulerTickTimeout = obj.clear; } function fakeMidnightPingFuzzingDelay(delayMs) { @@ -171,6 +260,11 @@ function fakeMidnightPingFuzzingDelay(delayMs) { module.Policy.midnightPingFuzzingDelay = () => delayMs; } +function fakeGeneratePingId(func) { + let module = Cu.import("resource://gre/modules/TelemetryController.jsm"); + module.Policy.generatePingId = func; +} + // Return a date that is |offset| ms in the future from |date|. function futureDate(date, offset) { return new Date(date.getTime() + offset); @@ -191,12 +285,18 @@ if (runningInParent) { Services.prefs.setCharPref("toolkit.telemetry.log.level", "Trace"); // Telemetry archiving should be on. Services.prefs.setBoolPref("toolkit.telemetry.archive.enabled", true); + + fakePingSendTimer((callback, timeout) => { + Services.tm.mainThread.dispatch(() => callback(), Ci.nsIThread.DISPATCH_NORMAL); + }, + () => {}); + + do_register_cleanup(() => TelemetrySend.shutdown()); } TelemetryController.initLogging(); // Avoid timers interrupting test behavior. fakeSchedulerTimer(() => {}, () => {}); -fakePingSendTimer(() => {}, () => {}); // Make pind sending predictable. fakeMidnightPingFuzzingDelay(0); diff --git a/toolkit/components/telemetry/tests/unit/test_PingAPI.js b/toolkit/components/telemetry/tests/unit/test_PingAPI.js index 9d0d81b7fa3c..b607fe2f3439 100644 --- a/toolkit/components/telemetry/tests/unit/test_PingAPI.js +++ b/toolkit/components/telemetry/tests/unit/test_PingAPI.js @@ -9,6 +9,7 @@ Cu.import("resource://gre/modules/TelemetryController.jsm", this); Cu.import("resource://gre/modules/TelemetrySession.jsm", this); Cu.import("resource://gre/modules/TelemetryArchive.jsm", this); +Cu.import("resource://gre/modules/TelemetrySend.jsm", this); Cu.import("resource://gre/modules/XPCOMUtils.jsm", this); Cu.import("resource://gre/modules/osfile.jsm", this); Cu.import("resource://gre/modules/Task.jsm", this); @@ -122,7 +123,7 @@ add_task(function* test_archivedPings() { yield checkLoadingPings(); // Check that we find the archived pings again by scanning after a restart. - TelemetryController.reset(); + yield TelemetryController.reset(); let pingList = yield TelemetryArchive.promiseArchivedPingList(); Assert.deepEqual(expectedPingList, pingList, @@ -367,14 +368,14 @@ add_task(function* test_archiveCleanup() { add_task(function* test_clientId() { // Check that a ping submitted after the delayed telemetry initialization completed // should get a valid client id. - yield TelemetryController.setup(); + yield TelemetryController.reset(); const clientId = TelemetryController.clientID; let id = yield TelemetryController.submitExternalPing("test-type", {}, {addClientId: true}); let ping = yield TelemetryArchive.promiseArchivedPingById(id); Assert.ok(!!ping, "Should have loaded the ping."); - Assert.ok("clientId" in ping, "Ping should have a client id.") + Assert.ok("clientId" in ping, "Ping should have a client id."); Assert.ok(UUID_REGEX.test(ping.clientId), "Client id is in UUID format."); Assert.equal(ping.clientId, clientId, "Ping client id should match the global client id."); @@ -441,3 +442,7 @@ add_task(function* test_currentPingData() { Assert.equal(ping.payload.keyedHistograms[id]["a"].sum, 1, "Keyed test value should match."); } }); + +add_task(function* test_shutdown() { + yield TelemetrySend.shutdown(); +}); diff --git a/toolkit/components/telemetry/tests/unit/test_SubsessionChaining.js b/toolkit/components/telemetry/tests/unit/test_SubsessionChaining.js index fe151f19afb1..df2cc6481098 100644 --- a/toolkit/components/telemetry/tests/unit/test_SubsessionChaining.js +++ b/toolkit/components/telemetry/tests/unit/test_SubsessionChaining.js @@ -233,5 +233,6 @@ add_task(function* test_subsessionsChaining() { }); add_task(function* () { + yield TelemetrySend.shutdown(); do_test_finished(); }); diff --git a/toolkit/components/telemetry/tests/unit/test_TelemetryController.js b/toolkit/components/telemetry/tests/unit/test_TelemetryController.js index 0a9daab24ade..b4a27e989322 100644 --- a/toolkit/components/telemetry/tests/unit/test_TelemetryController.js +++ b/toolkit/components/telemetry/tests/unit/test_TelemetryController.js @@ -8,7 +8,6 @@ * checked in the second request. */ -Cu.import("resource://testing-common/httpd.js", this); Cu.import("resource://gre/modules/ClientID.jsm"); Cu.import("resource://gre/modules/Services.jsm"); Cu.import("resource://gre/modules/XPCOMUtils.jsm", this); @@ -37,14 +36,11 @@ const PREF_UNIFIED = PREF_BRANCH + "unified"; const Telemetry = Cc["@mozilla.org/base/telemetry;1"].getService(Ci.nsITelemetry); -let gHttpServer = new HttpServer(); -let gServerStarted = false; -let gRequestIterator = null; let gClientID = null; function sendPing(aSendClientId, aSendEnvironment) { - if (gServerStarted) { - TelemetrySend.setServer("http://localhost:" + gHttpServer.identity.primaryPort); + if (PingServer.started) { + TelemetrySend.setServer("http://localhost:" + PingServer.port); } else { TelemetrySend.setServer("http://doesnotexist"); } @@ -56,24 +52,6 @@ function sendPing(aSendClientId, aSendEnvironment) { return TelemetryController.submitExternalPing(TEST_PING_TYPE, {}, options); } -function wrapWithExceptionHandler(f) { - function wrapper(...args) { - try { - f(...args); - } catch (ex if typeof(ex) == 'object') { - dump("Caught exception: " + ex.message + "\n"); - dump(ex.stack); - do_test_finished(); - } - } - return wrapper; -} - -function registerPingHandler(handler) { - gHttpServer.registerPrefixHandler("/submit/telemetry/", - wrapWithExceptionHandler(handler)); -} - function checkPingFormat(aPing, aType, aHasClientId, aHasEnvironment) { const MANDATORY_PING_FIELDS = [ "type", "id", "creationDate", "version", "application", "payload" @@ -114,15 +92,6 @@ function checkPingFormat(aPing, aType, aHasClientId, aHasEnvironment) { Assert.equal("environment" in aPing, aHasEnvironment); } -/** - * Start the webserver used in the tests. - */ -function startWebserver() { - gHttpServer.start(-1); - gServerStarted = true; - gRequestIterator = Iterator(new Request()); -} - function run_test() { do_test_pending(); @@ -159,10 +128,10 @@ add_task(function* test_overwritePing() { // Checks that a sent ping is correctly received by a dummy http server. add_task(function* test_simplePing() { - startWebserver(); + PingServer.start(); yield sendPing(false, false); - let request = yield gRequestIterator.next(); + let request = yield PingServer.promiseNextRequest(); // Check that we have a version query parameter in the URL. Assert.notEqual(request.queryString, ""); @@ -186,8 +155,7 @@ add_task(function* test_deletionPing() { // Disable FHR upload: this should trigger a deletion ping. Preferences.set(PREF_FHR_UPLOAD_ENABLED, false); - let request = yield gRequestIterator.next(); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); checkPingFormat(ping, DELETION_PING_TYPE, true, false); // Restore FHR Upload. @@ -198,8 +166,7 @@ add_task(function* test_pingHasClientId() { // Send a ping with a clientId. yield sendPing(true, false); - let request = yield gRequestIterator.next(); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); checkPingFormat(ping, TEST_PING_TYPE, true, false); if (HAS_DATAREPORTINGSERVICE && @@ -212,8 +179,7 @@ add_task(function* test_pingHasClientId() { add_task(function* test_pingHasEnvironment() { // Send a ping with the environment data. yield sendPing(false, true); - let request = yield gRequestIterator.next(); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); checkPingFormat(ping, TEST_PING_TYPE, false, true); // Test a field in the environment build section. @@ -223,8 +189,7 @@ add_task(function* test_pingHasEnvironment() { add_task(function* test_pingHasEnvironmentAndClientId() { // Send a ping with the environment data and client id. yield sendPing(true, true); - let request = yield gRequestIterator.next(); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); checkPingFormat(ping, TEST_PING_TYPE, true, true); // Test a field in the environment build section. @@ -254,13 +219,12 @@ add_task(function* test_archivePings() { // If we're using unified telemetry, disabling ping upload will generate a "deletion" // ping. Catch it. if (isUnified) { - let request = yield gRequestIterator.next(); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); checkPingFormat(ping, DELETION_PING_TYPE, true, false); } // Register a new Ping Handler that asserts if a ping is received, then send a ping. - registerPingHandler(() => Assert.ok(false, "Telemetry must not send pings if not allowed to.")); + PingServer.registerPingHandler(() => Assert.ok(false, "Telemetry must not send pings if not allowed to.")); let pingId = yield sendPing(true, true); // Check that the ping was archived, even with upload disabled. @@ -282,12 +246,12 @@ add_task(function* test_archivePings() { now = new Date(2014, 06, 18, 22, 0, 0); fakeNow(now); - // Restore the non asserting ping handler. This is done by the Request() constructor. - gRequestIterator = Iterator(new Request()); + // Restore the non asserting ping handler. + PingServer.resetPingHandler(); pingId = yield sendPing(true, true); // Check that we archive pings when successfully sending them. - yield gRequestIterator.next(); + yield PingServer.promiseNextPing(); ping = yield TelemetryArchive.promiseArchivedPingById(pingId); Assert.equal(ping.id, pingId, "TelemetryController should still archive pings if ping upload is enabled."); @@ -301,62 +265,62 @@ add_task(function* test_midnightPingSendFuzzing() { let now = new Date(2030, 5, 1, 11, 00, 0); fakeNow(now); - let pingSendTimerCallback = null; - let pingSendTimeout = null; - fakePingSendTimer((callback, timeout) => { - pingSendTimerCallback = callback; - pingSendTimeout = timeout; - }, () => {}); + let waitForTimer = () => new Promise(resolve => { + fakePingSendTimer((callback, timeout) => { + resolve([callback, timeout]); + }, () => {}); + }); - gRequestIterator = Iterator(new Request()); + PingServer.clearRequests(); yield TelemetryController.reset(); // A ping after midnight within the fuzzing delay should not get sent. now = new Date(2030, 5, 2, 0, 40, 0); fakeNow(now); - registerPingHandler((req, res) => { + PingServer.registerPingHandler((req, res) => { Assert.ok(false, "No ping should be received yet."); }); + let timerPromise = waitForTimer(); yield sendPing(true, true); - Assert.ok(!!pingSendTimerCallback); - Assert.deepEqual(futureDate(now, pingSendTimeout), new Date(2030, 5, 2, 1, 0, 0)); + let [timerCallback, timerTimeout] = yield timerPromise; + Assert.ok(!!timerCallback); + Assert.deepEqual(futureDate(now, timerTimeout), new Date(2030, 5, 2, 1, 0, 0)); // A ping just before the end of the fuzzing delay should not get sent. now = new Date(2030, 5, 2, 0, 59, 59); fakeNow(now); - pingSendTimeout = null; + timerPromise = waitForTimer(); yield sendPing(true, true); - Assert.deepEqual(futureDate(now, pingSendTimeout), new Date(2030, 5, 2, 1, 0, 0)); + [timerCallback, timerTimeout] = yield timerPromise; + Assert.deepEqual(timerTimeout, 1 * 1000); - // The Request constructor restores the previous ping handler. - gRequestIterator = Iterator(new Request()); + // Restore the previous ping handler. + PingServer.resetPingHandler(); // Setting the clock to after the fuzzing delay, we should trigger the two ping sends // with the timer callback. - now = futureDate(now, pingSendTimeout); + now = futureDate(now, timerTimeout); fakeNow(now); - yield pingSendTimerCallback(); - let requests = []; - requests.push(yield gRequestIterator.next()); - requests.push(yield gRequestIterator.next()); - for (let req of requests) { - let ping = decodeRequestPayload(req); + yield timerCallback(); + const pings = yield PingServer.promiseNextPings(2); + for (let ping of pings) { checkPingFormat(ping, TEST_PING_TYPE, true, true); } + yield TelemetrySend.testWaitOnOutgoingPings(); // Moving the clock further we should still send pings immediately. now = futureDate(now, 5 * 60 * 1000); yield sendPing(true, true); - let request = yield gRequestIterator.next(); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); checkPingFormat(ping, TEST_PING_TYPE, true, true); + yield TelemetrySend.testWaitOnOutgoingPings(); // Check that pings shortly before midnight are immediately sent. now = fakeNow(2030, 5, 3, 23, 59, 0); yield sendPing(true, true); - request = yield gRequestIterator.next(); - ping = decodeRequestPayload(request); + ping = yield PingServer.promiseNextPing(); checkPingFormat(ping, TEST_PING_TYPE, true, true); + yield TelemetrySend.testWaitOnOutgoingPings(); // Clean-up. fakeMidnightPingFuzzingDelay(0); @@ -381,31 +345,6 @@ add_task(function* test_changePingAfterSubmission() { }); add_task(function* stopServer(){ - gHttpServer.stop(do_test_finished); + yield PingServer.stop(); + do_test_finished(); }); - -// An iterable sequence of http requests -function Request() { - let defers = []; - let current = 0; - - function RequestIterator() {} - - // Returns a promise that resolves to the next http request - RequestIterator.prototype.next = function() { - let deferred = defers[current++]; - return deferred.promise; - } - - this.__iterator__ = function(){ - return new RequestIterator(); - } - - registerPingHandler((request, response) => { - let deferred = defers[defers.length - 1]; - defers.push(Promise.defer()); - deferred.resolve(request); - }); - - defers.push(Promise.defer()); -} diff --git a/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js b/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js new file mode 100644 index 000000000000..74dc1ec32cd8 --- /dev/null +++ b/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js @@ -0,0 +1,263 @@ +/* Any copyright is dedicated to the Public Domain. + http://creativecommons.org/publicdomain/zero/1.0/ +*/ + +// This tests the public Telemetry API for submitting pings. + +"use strict"; + +Cu.import("resource://gre/modules/TelemetryController.jsm", this); +Cu.import("resource://gre/modules/TelemetrySession.jsm", this); +Cu.import("resource://gre/modules/TelemetrySend.jsm", this); +Cu.import("resource://gre/modules/TelemetryUtils.jsm", this); +Cu.import("resource://gre/modules/Services.jsm", this); +Cu.import("resource://gre/modules/Preferences.jsm", this); +Cu.import("resource://gre/modules/osfile.jsm", this); + +const PREF_TELEMETRY_ENABLED = "toolkit.telemetry.enabled"; +const PREF_TELEMETRY_SERVER = "toolkit.telemetry.server"; + +const MS_IN_A_MINUTE = 60 * 1000; + +function countPingTypes(pings) { + let countByType = new Map(); + for (let p of pings) { + countByType.set(p.type, 1 + (countByType.get(p.type) || 0)); + } + return countByType; +} + +function setPingLastModified(id, timestamp) { + const path = OS.Path.join(TelemetryStorage.pingDirectoryPath, id); + return OS.File.setDates(path, null, timestamp); +} + +// Mock out the send timer activity. +function waitForTimer() { + return new Promise(resolve => { + fakePingSendTimer((callback, timeout) => { + resolve([callback, timeout]); + }, () => {}); + }); +} + +// Allow easy faking of readable ping ids. +// This helps with debugging issues with e.g. ordering in the send logic. +function fakePingId(type, number) { + const HEAD = "93bd0011-2c8f-4e1c-bee0-"; + const TAIL = "000000000000"; + const N = String(number); + const id = HEAD + type + TAIL.slice(type.length, - N.length) + N; + fakeGeneratePingId(() => id); + return id; +} + +let checkPingsSaved = Task.async(function* (pingIds) { + let allFound = true; + for (let id of pingIds) { + const path = OS.Path.join(TelemetryStorage.pingDirectoryPath, id); + let exists = false; + try { + exists = yield OS.File.exists(path); + } catch (ex) {} + + if (!exists) { + dump("checkPingsSaved - failed to find ping: " + path + "\n"); + allFound = false; + } + } + + return allFound; +}); + +function run_test() { + // Trigger a proper telemetry init. + do_get_profile(true); + Services.prefs.setBoolPref(PREF_TELEMETRY_ENABLED, true); + run_next_test(); +} + +// Test the ping sending logic. +add_task(function* test_sendPendingPings() { + const TYPE_PREFIX = "test-sendPendingPings-"; + const TEST_TYPE_A = TYPE_PREFIX + "A"; + const TEST_TYPE_B = TYPE_PREFIX + "B"; + + const TYPE_A_COUNT = 20; + const TYPE_B_COUNT = 5; + + // Fake a current date. + let now = TelemetryUtils.truncateToDays(new Date()); + now = fakeNow(futureDate(now, 10 * 60 * MS_IN_A_MINUTE)); + + // Enable test-mode for TelemetrySend, otherwise we won't store pending pings + // before the module is fully initialized later. + TelemetrySend.setTestModeEnabled(true); + + // Submit some pings without the server and telemetry started yet. + for (let i = 0; i < TYPE_A_COUNT; ++i) { + fakePingId("a", i); + const id = yield TelemetryController.submitExternalPing(TEST_TYPE_A, {}); + yield setPingLastModified(id, now.getTime() + (i * 1000)); + } + + Assert.equal(TelemetrySend.pendingPingCount, TYPE_A_COUNT, + "Should have correct pending ping count"); + + // Submit some more pings of a different type. + now = fakeNow(futureDate(now, 5 * MS_IN_A_MINUTE)); + for (let i = 0; i < TYPE_B_COUNT; ++i) { + fakePingId("b", i); + const id = yield TelemetryController.submitExternalPing(TEST_TYPE_B, {}); + yield setPingLastModified(id, now.getTime() + (i * 1000)); + } + + Assert.equal(TelemetrySend.pendingPingCount, TYPE_A_COUNT + TYPE_B_COUNT, + "Should have correct pending ping count"); + + // Now enable sending to the ping server. + now = fakeNow(futureDate(now, MS_IN_A_MINUTE)); + PingServer.start(); + Preferences.set(PREF_TELEMETRY_SERVER, "http://localhost:" + PingServer.port); + + let timerPromise = waitForTimer(); + yield TelemetryController.reset(); + let [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + Assert.ok(!!pingSendTimerCallback, "Should have a timer callback"); + + // We should have received 10 pings from the first send batch: + // 5 of type B and 5 of type A, as sending is newest-first. + // The other pings should be delayed by the 10-pings-per-minute limit. + let pings = yield PingServer.promiseNextPings(10); + Assert.equal(TelemetrySend.pendingPingCount, TYPE_A_COUNT - 5, + "Should have correct pending ping count"); + PingServer.registerPingHandler(() => Assert.ok(false, "Should not have received any pings now")); + let countByType = countPingTypes(pings); + + Assert.equal(countByType.get(TEST_TYPE_B), TYPE_B_COUNT, + "Should have received the correct amount of type B pings"); + Assert.equal(countByType.get(TEST_TYPE_A), 10 - TYPE_B_COUNT, + "Should have received the correct amount of type A pings"); + + // As we hit the ping send limit and still have pending pings, a send tick should + // be scheduled in a minute. + Assert.ok(!!pingSendTimerCallback, "Timer callback should be set"); + Assert.equal(pingSendTimeout, MS_IN_A_MINUTE, "Send tick timeout should be correct"); + + // Trigger the next tick - we should receive the next 10 type A pings. + PingServer.resetPingHandler(); + now = fakeNow(futureDate(now, pingSendTimeout)); + timerPromise = waitForTimer(); + pingSendTimerCallback(); + [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + + pings = yield PingServer.promiseNextPings(10); + PingServer.registerPingHandler(() => Assert.ok(false, "Should not have received any pings now")); + countByType = countPingTypes(pings); + + Assert.equal(countByType.get(TEST_TYPE_A), 10, "Should have received the correct amount of type A pings"); + + // We hit the ping send limit again and still have pending pings, a send tick should + // be scheduled in a minute. + Assert.equal(pingSendTimeout, MS_IN_A_MINUTE, "Send tick timeout should be correct"); + + // Trigger the next tick - we should receive the remaining type A pings. + PingServer.resetPingHandler(); + now = fakeNow(futureDate(now, pingSendTimeout)); + yield pingSendTimerCallback(); + + pings = yield PingServer.promiseNextPings(5); + PingServer.registerPingHandler(() => Assert.ok(false, "Should not have received any pings now")); + countByType = countPingTypes(pings); + + Assert.equal(countByType.get(TEST_TYPE_A), 5, "Should have received the correct amount of type A pings"); +}); + +// Test the backoff timeout behavior after send failures. +add_task(function* test_backoffTimeout() { + const TYPE_PREFIX = "test-backoffTimeout-"; + const TEST_TYPE_C = TYPE_PREFIX + "C"; + const TEST_TYPE_D = TYPE_PREFIX + "D"; + const TEST_TYPE_E = TYPE_PREFIX + "E"; + + // Failing a ping send now should trigger backoff behavior. + let now = fakeNow(2010, 1, 1, 11, 0, 0); + yield TelemetrySend.reset(); + PingServer.stop(); + fakePingId("c", 0); + now = fakeNow(futureDate(now, MS_IN_A_MINUTE)); + let timerPromise = waitForTimer(); + yield TelemetryController.submitExternalPing(TEST_TYPE_C, {}); + let [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + Assert.equal(TelemetrySend.pendingPingCount, 1, "Should have one pending ping."); + + const MAX_BACKOFF_TIMEOUT = 120 * MS_IN_A_MINUTE; + for (let timeout = 2 * MS_IN_A_MINUTE; timeout <= MAX_BACKOFF_TIMEOUT; timeout *= 2) { + Assert.ok(!!pingSendTimerCallback, "Should have received a timer callback"); + Assert.equal(pingSendTimeout, timeout, "Send tick timeout should be correct"); + + let callback = pingSendTimerCallback; + now = fakeNow(futureDate(now, pingSendTimeout)); + timerPromise = waitForTimer(); + yield callback(); + [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + } + + timerPromise = waitForTimer(); + yield pingSendTimerCallback(); + [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + Assert.equal(pingSendTimeout, MAX_BACKOFF_TIMEOUT, "Tick timeout should be capped"); + + // Submitting a new ping should reset the backoff behavior. + fakePingId("d", 0); + now = fakeNow(futureDate(now, MS_IN_A_MINUTE)); + timerPromise = waitForTimer(); + yield TelemetryController.submitExternalPing(TEST_TYPE_D, {}); + [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + Assert.equal(pingSendTimeout, 2 * MS_IN_A_MINUTE, "Send tick timeout should be correct"); + + // With the server running again, we should send out the pending pings immediately + // when a new ping is submitted. + PingServer.start(); + TelemetrySend.setServer("http://localhost:" + PingServer.port); + fakePingId("e", 0); + now = fakeNow(futureDate(now, MS_IN_A_MINUTE)); + timerPromise = waitForTimer(); + yield TelemetryController.submitExternalPing(TEST_TYPE_E, {}); + + let pings = yield PingServer.promiseNextPings(3); + let countByType = countPingTypes(pings); + + Assert.equal(countByType.get(TEST_TYPE_C), 1, "Should have received the correct amount of type C pings"); + Assert.equal(countByType.get(TEST_TYPE_D), 1, "Should have received the correct amount of type D pings"); + Assert.equal(countByType.get(TEST_TYPE_E), 1, "Should have received the correct amount of type E pings"); + + yield TelemetrySend.testWaitOnOutgoingPings(); + Assert.equal(TelemetrySend.pendingPingCount, 0, "Should have no pending pings left"); +}); + +// Test that the current, non-persisted pending pings are properly saved on shutdown. +add_task(function* test_persistCurrentPingsOnShutdown() { + const TEST_TYPE = "test-persistCurrentPingsOnShutdown"; + const PING_COUNT = 5; + yield TelemetrySend.reset(); + PingServer.stop(); + Assert.equal(TelemetrySend.pendingPingCount, 0, "Should have no pending pings yet"); + + // Submit new pings that shouldn't be persisted yet. + let ids = []; + for (let i=0; i<5; ++i) { + ids.push(fakePingId("f", i)); + TelemetryController.submitExternalPing(TEST_TYPE, {}); + } + + Assert.equal(TelemetrySend.pendingPingCount, PING_COUNT, "Should have the correct pending ping count"); + + // Triggering a shutdown should persist the pings. + yield TelemetrySend.shutdown(); + Assert.ok((yield checkPingsSaved(ids)), "All pending pings should have been persisted"); + + // After a restart the pings should have been found when scanning. + yield TelemetrySend.reset(); + Assert.equal(TelemetrySend.pendingPingCount, PING_COUNT, "Should have the correct pending ping count"); +}); diff --git a/toolkit/components/telemetry/tests/unit/test_TelemetrySendOldPings.js b/toolkit/components/telemetry/tests/unit/test_TelemetrySendOldPings.js index afe8b7e5a7b3..4022f6d66559 100644 --- a/toolkit/components/telemetry/tests/unit/test_TelemetrySendOldPings.js +++ b/toolkit/components/telemetry/tests/unit/test_TelemetrySendOldPings.js @@ -14,7 +14,6 @@ Cu.import("resource://gre/modules/osfile.jsm", this); Cu.import("resource://gre/modules/Services.jsm", this); -Cu.import("resource://testing-common/httpd.js", this); Cu.import("resource://gre/modules/Promise.jsm", this); Cu.import("resource://gre/modules/TelemetryStorage.jsm", this); Cu.import("resource://gre/modules/TelemetryController.jsm", this); @@ -45,7 +44,6 @@ const LRU_PINGS = TelemetrySend.MAX_LRU_PINGS; const TOTAL_EXPECTED_PINGS = OVERDUE_PINGS + RECENT_PINGS + OLD_FORMAT_PINGS; -let gHttpServer = new HttpServer(); let gCreatedPings = 0; let gSeenPings = 0; @@ -146,20 +144,6 @@ function pingHandler(aRequest) { gSeenPings++; } -/** - * Returns a Promise that resolves when gHttpServer has been - * successfully shut down. - * - * @returns Promise - */ -function stopHttpServer() { - let deferred = Promise.defer(); - gHttpServer.stop(function() { - deferred.resolve(); - }) - return deferred.promise; -} - /** * Clear out all pending pings. */ @@ -179,8 +163,8 @@ function startTelemetry() { } function run_test() { - gHttpServer.registerPrefixHandler("/submit/telemetry/", pingHandler); - gHttpServer.start(-1); + PingServer.start(); + PingServer.registerPingHandler(pingHandler); do_get_profile(); loadAddonManager("xpcshell@tests.mozilla.org", "XPCShell", "1", "1.9.2"); @@ -191,7 +175,7 @@ function run_test() { Services.prefs.setBoolPref(TelemetryController.Constants.PREF_ENABLED, true); Services.prefs.setCharPref(TelemetryController.Constants.PREF_SERVER, - "http://localhost:" + gHttpServer.identity.primaryPort); + "http://localhost:" + PingServer.port); run_next_test(); } @@ -224,14 +208,15 @@ add_task(function* test_expired_pings_are_deleted() { }); /** - * Test that really recent pings are not sent on Telemetry initialization. + * Test that really recent pings are sent on Telemetry initialization. */ -add_task(function* test_recent_pings_not_sent() { +add_task(function* test_recent_pings_sent() { let pingTypes = [{ num: RECENT_PINGS }]; let recentPings = yield createSavedPings(pingTypes); yield TelemetryController.reset(); - assertReceivedPings(0); + yield TelemetrySend.testWaitOnOutgoingPings(); + assertReceivedPings(RECENT_PINGS); yield clearPendingPings(); }); @@ -248,6 +233,9 @@ add_task(function* test_most_recent_pings_kept() { let head = pings.slice(0, LRU_PINGS); let tail = pings.slice(-3); + const evictedHistogram = Services.telemetry.getHistogramById('TELEMETRY_FILES_EVICTED'); + evictedHistogram.clear(); + yield TelemetryController.reset(); const pending = yield TelemetryStorage.loadPendingPingList(); @@ -257,6 +245,9 @@ add_task(function* test_most_recent_pings_kept() { } assertNotSaved(tail); + Assert.equal(evictedHistogram.snapshot().sum, tail.length, + "Should have tracked the evicted ping count"); + yield TelemetrySend.shutdown(); yield clearPendingPings(); }); @@ -318,6 +309,7 @@ add_task(function* test_overdue_old_format() { yield File.setDates(PING_FILES_PATHS[f], null, Date.now() - OVERDUE_PING_FILE_AGE); } + gSeenPings = 0; yield TelemetryController.reset(); yield TelemetrySend.testWaitOnOutgoingPings(); assertReceivedPings(OLD_FORMAT_PINGS); @@ -353,6 +345,11 @@ add_task(function* test_overdue_pings_trigger_send() { yield assertNotSaved(expiredPings); yield assertNotSaved(overduePings); + Assert.equal(TelemetrySend.overduePingsCount, overduePings.length, + "Should have tracked the correct amount of overdue pings"); + Assert.equal(TelemetrySend.discardedPingsCount, expiredPings.length, + "Should have tracked the correct amount of expired pings"); + yield clearPendingPings(); }); @@ -388,7 +385,7 @@ add_task(function* test_overdue_old_format() { let receivedPings = 0; // Register a new prefix handler to validate the URL. - gHttpServer.registerPrefixHandler("/submit/telemetry/", request => { + PingServer.registerPingHandler(request => { // Check that we have a version query parameter in the URL. Assert.notEqual(request.queryString, ""); @@ -407,5 +404,5 @@ add_task(function* test_overdue_old_format() { }); add_task(function* teardown() { - yield stopHttpServer(); + yield PingServer.stop(); }); diff --git a/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js b/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js index d1bfe44cb9bd..7215087a8d99 100644 --- a/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js +++ b/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js @@ -8,7 +8,6 @@ * checked in the second request. */ -Cu.import("resource://testing-common/httpd.js", this); Cu.import("resource://services-common/utils.js"); Cu.import("resource://gre/modules/ClientID.jsm"); Cu.import("resource://gre/modules/Services.jsm"); @@ -77,9 +76,6 @@ XPCOMUtils.defineLazyGetter(this, "DATAREPORTING_PATH", function() { return OS.Path.join(OS.Constants.Path.profileDir, DATAREPORTING_DIR); }); -let gHttpServer = new HttpServer(); -let gServerStarted = false; -let gRequestIterator = null; let gClientID = null; function generateUUID() { @@ -97,8 +93,8 @@ function truncateDateToDays(date) { function sendPing() { TelemetrySession.gatherStartup(); - if (gServerStarted) { - TelemetrySend.setServer("http://localhost:" + gHttpServer.identity.primaryPort); + if (PingServer.started) { + TelemetrySend.setServer("http://localhost:" + PingServer.port); return TelemetrySession.testPing(); } else { TelemetrySend.setServer("http://doesnotexist"); @@ -113,19 +109,6 @@ let clearPendingPings = Task.async(function*() { } }); -function wrapWithExceptionHandler(f) { - function wrapper(...args) { - try { - f(...args); - } catch (ex if typeof(ex) == 'object') { - dump("Caught exception: " + ex.message + "\n"); - dump(ex.stack); - do_test_finished(); - } - } - return wrapper; -} - function fakeGenerateUUID(sessionFunc, subsessionFunc) { let session = Cu.import("resource://gre/modules/TelemetrySession.jsm"); session.Policy.generateSessionUUID = sessionFunc; @@ -137,11 +120,6 @@ function fakeIdleNotification(topic) { return session.TelemetryScheduler.observe(null, topic, null); } -function registerPingHandler(handler) { - gHttpServer.registerPrefixHandler("/submit/telemetry/", - wrapWithExceptionHandler(handler)); -} - function setupTestData() { Telemetry.newHistogram(IGNORE_HISTOGRAM, "never", Telemetry.HISTOGRAM_BOOLEAN); Telemetry.histogramFrom(IGNORE_CLONED_HISTOGRAM, IGNORE_HISTOGRAM_TO_CLONE); @@ -533,10 +511,10 @@ add_task(function* test_noServerPing() { // Checks that a sent ping is correctly received by a dummy http server. add_task(function* test_simplePing() { - gHttpServer.start(-1); - gServerStarted = true; - gRequestIterator = Iterator(new Request()); - Preferences.set(PREF_SERVER, "http://localhost:" + gHttpServer.identity.primaryPort); + yield clearPendingPings(); + yield TelemetrySend.reset(); + PingServer.start(); + Preferences.set(PREF_SERVER, "http://localhost:" + PingServer.port); let now = new Date(2020, 1, 1, 12, 0, 0); let expectedDate = new Date(2020, 1, 1, 0, 0, 0); @@ -553,8 +531,7 @@ add_task(function* test_simplePing() { fakeNow(new Date(2020, 1, 1, 12, SESSION_DURATION_IN_MINUTES, 0)); yield sendPing(); - let request = yield gRequestIterator.next(); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); checkPingFormat(ping, PING_TYPE_MAIN, true, true); @@ -579,7 +556,7 @@ add_task(function* test_saveLoadPing() { // Let's start out with a defined state. yield clearPendingPings(); yield TelemetryController.reset(); - gRequestIterator = Iterator(new Request()); + PingServer.clearRequests(); // Setup test data and trigger pings. setupTestData(); @@ -587,10 +564,7 @@ add_task(function* test_saveLoadPing() { yield sendPing(); // Get requests received by dummy server. - let requests = [ - yield gRequestIterator.next(), - yield gRequestIterator.next(), - ]; + const requests = yield PingServer.promiseNextRequests(2); for (let req of requests) { Assert.equal(req.getHeader("content-type"), "application/json; charset=UTF-8", @@ -858,7 +832,7 @@ add_task(function* test_dailyCollection() { let nowDay = new Date(2030, 1, 1, 0, 0, 0); let schedulerTickCallback = null; - gRequestIterator = Iterator(new Request()); + PingServer.clearRequests(); fakeNow(now); @@ -866,8 +840,9 @@ add_task(function* test_dailyCollection() { fakeSchedulerTimer(callback => schedulerTickCallback = callback, () => {}); // Init and check timer. + yield clearPendingPings(); yield TelemetrySession.setup(); - TelemetrySend.setServer("http://localhost:" + gHttpServer.identity.primaryPort); + TelemetrySend.setServer("http://localhost:" + PingServer.port); // Set histograms to expected state. const COUNT_ID = "TELEMETRY_TEST_COUNT"; @@ -892,9 +867,8 @@ add_task(function* test_dailyCollection() { yield schedulerTickCallback(); // Collect the daily ping. - let request = yield gRequestIterator.next(); - Assert.ok(!!request); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); + Assert.ok(!!ping); Assert.equal(ping.type, PING_TYPE_MAIN); Assert.equal(ping.payload.info.reason, REASON_DAILY); @@ -913,9 +887,8 @@ add_task(function* test_dailyCollection() { // Run a scheduler tick. Trigger and collect another ping. The histograms should be reset. yield schedulerTickCallback(); - request = yield gRequestIterator.next(); - Assert.ok(!!request); - ping = decodeRequestPayload(request); + ping = yield PingServer.promiseNextPing(); + Assert.ok(!!ping); Assert.equal(ping.type, PING_TYPE_MAIN); Assert.equal(ping.payload.info.reason, REASON_DAILY); @@ -936,9 +909,8 @@ add_task(function* test_dailyCollection() { fakeNow(now); yield schedulerTickCallback(); - request = yield gRequestIterator.next(); - Assert.ok(!!request); - ping = decodeRequestPayload(request); + ping = yield PingServer.promiseNextPing(); + Assert.ok(!!ping); Assert.equal(ping.type, PING_TYPE_MAIN); Assert.equal(ping.payload.info.reason, REASON_DAILY); @@ -959,7 +931,7 @@ add_task(function* test_dailyDuplication() { return; } - gRequestIterator = Iterator(new Request()); + PingServer.clearRequests(); let schedulerTickCallback = null; let now = new Date(2030, 1, 1, 0, 0, 0); @@ -979,15 +951,14 @@ add_task(function* test_dailyDuplication() { yield schedulerTickCallback(); // Get the first daily ping. - let request = yield gRequestIterator.next(); - Assert.ok(!!request); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); + Assert.ok(!!ping); Assert.equal(ping.type, PING_TYPE_MAIN); Assert.equal(ping.payload.info.reason, REASON_DAILY); // We don't expect to receive any other daily ping in this test, so assert if we do. - registerPingHandler((req, res) => { + PingServer.registerPingHandler((req, res) => { Assert.ok(false, "No more daily pings should be sent/received in this test."); }); @@ -1003,6 +974,7 @@ add_task(function* test_dailyDuplication() { // Shutdown to cleanup the aborted-session if it gets created. yield TelemetrySession.shutdown(); + PingServer.resetPingHandler(); }); add_task(function* test_dailyOverdue() { @@ -1023,7 +995,7 @@ add_task(function* test_dailyOverdue() { fakeNow(now); // Assert if we receive something! - registerPingHandler((req, res) => { + PingServer.registerPingHandler((req, res) => { Assert.ok(false, "No daily ping should be received if not overdue!."); }); @@ -1031,8 +1003,9 @@ add_task(function* test_dailyOverdue() { Assert.ok(!!schedulerTickCallback); yield schedulerTickCallback(); - // Restore the non asserting ping handler. This is done by the Request() constructor. - gRequestIterator = Iterator(new Request()); + // Restore the non asserting ping handler. + PingServer.resetPingHandler(); + PingServer.clearRequests(); // Simulate an overdue ping: we're not close to midnight, but the last daily ping // time is too long ago. @@ -1044,9 +1017,8 @@ add_task(function* test_dailyOverdue() { yield schedulerTickCallback(); // Get the first daily ping. - let request = yield gRequestIterator.next(); - Assert.ok(!!request); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); + Assert.ok(!!ping); Assert.equal(ping.type, PING_TYPE_MAIN); Assert.equal(ping.payload.info.reason, REASON_DAILY); @@ -1065,7 +1037,8 @@ add_task(function* test_environmentChange() { let timerCallback = null; let timerDelay = null; - gRequestIterator = Iterator(new Request()); + clearPendingPings(); + PingServer.clearRequests(); fakeNow(now); @@ -1078,7 +1051,7 @@ add_task(function* test_environmentChange() { // Setup. yield TelemetrySession.setup(); - TelemetrySend.setServer("http://localhost:" + gHttpServer.identity.primaryPort); + TelemetrySend.setServer("http://localhost:" + PingServer.port); TelemetryEnvironment._watchPreferences(PREFS_TO_WATCH); // Set histograms to expected state. @@ -1099,9 +1072,8 @@ add_task(function* test_environmentChange() { fakeNow(now); Preferences.set(PREF_TEST, 1); - let request = yield gRequestIterator.next(); - Assert.ok(!!request); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); + Assert.ok(!!ping); Assert.equal(ping.type, PING_TYPE_MAIN); Assert.equal(ping.environment.settings.userPrefs[PREF_TEST], undefined); @@ -1118,9 +1090,8 @@ add_task(function* test_environmentChange() { fakeNow(now); Preferences.set(PREF_TEST, 2); - request = yield gRequestIterator.next(); - Assert.ok(!!request); - ping = decodeRequestPayload(request); + ping = yield PingServer.promiseNextPing(); + Assert.ok(!!ping); Assert.equal(ping.type, PING_TYPE_MAIN); Assert.equal(ping.environment.settings.userPrefs[PREF_TEST], 1); @@ -1150,7 +1121,7 @@ add_task(function* test_pruneOldPingFile() { add_task(function* test_savedPingsOnShutdown() { // On desktop, we expect both "saved-session" and "shutdown" pings. We only expect // the former on Android. - const expectedPings = (gIsAndroid) ? 1 : 2; + const expectedPingCount = (gIsAndroid) ? 1 : 2; // Assure that we store the ping properly when saving sessions on shutdown. // We make the TelemetrySession shutdown to trigger a session save. const dir = TelemetryStorage.pingDirectoryPath; @@ -1158,12 +1129,11 @@ add_task(function* test_savedPingsOnShutdown() { yield OS.File.makeDir(dir); yield TelemetrySession.shutdown(); + PingServer.clearRequests(); yield TelemetryController.reset(); - const pending = yield TelemetryStorage.loadPendingPingList(); - Assert.equal(pending.length, expectedPings, - "Should have the correct number of pending pings."); - const pings = [for (p of pending) yield TelemetryStorage.loadPendingPing(p.id)]; + const pings = yield PingServer.promiseNextPings(expectedPingCount); + for (let ping of pings) { Assert.ok("type" in ping); @@ -1366,35 +1336,17 @@ add_task(function* test_abortedSession() { yield TelemetryStorage.savePingToFile(abortedSessionPing, ABORTED_FILE, false); yield clearPendingPings(); - gRequestIterator = Iterator(new Request()); + PingServer.clearRequests(); yield TelemetrySession.reset(); yield TelemetryController.reset(); Assert.ok(!(yield OS.File.exists(ABORTED_FILE)), "The aborted session ping must be removed from the aborted session ping directory."); - // TelemetryStorage requires all the pings to have their ID as filename. When appending - // the aborted-session ping to the pending pings, we must verify that it exists. - const PENDING_PING_FILE = - OS.Path.join(TelemetryStorage.pingDirectoryPath, abortedSessionPing.id); - Assert.ok((yield OS.File.exists(PENDING_PING_FILE)), - "The aborted session ping must exist in the saved pings directory."); - - // Trigger sending the pending pings. - yield sendPing(); - - // We should receive two pings, one of them an aborted-session ping. - let requests = [ - yield gRequestIterator.next(), - yield gRequestIterator.next(), - ]; - let pings = [for (req of requests) decodeRequestPayload(req)].filter((p) => { - return p.type == PING_TYPE_MAIN && p.payload.info.reason == REASON_ABORTED_SESSION; - }); - - Assert.equal(pings.length, 1, "Should have received one aborted-session ping."); - let receivedPing = pings[0]; - Assert.equal(receivedPing.id, abortedSessionPing.id); + // We should have received an aborted-session ping. + const receivedPing = yield PingServer.promiseNextPing(); + Assert.equal(receivedPing.type, PING_TYPE_MAIN, "Should have the correct type"); + Assert.equal(receivedPing.payload.info.reason, REASON_ABORTED_SESSION, "Ping should have the correct reason"); yield TelemetrySession.shutdown(); }); @@ -1444,7 +1396,7 @@ add_task(function* test_abortedDailyCoalescing() { yield OS.File.removeDir(DATAREPORTING_PATH, { ignoreAbsent: true }); let schedulerTickCallback = null; - gRequestIterator = Iterator(new Request()); + PingServer.clearRequests(); let nowDate = new Date(2009, 10, 18, 0, 0, 0); fakeNow(nowDate); @@ -1466,8 +1418,7 @@ add_task(function* test_abortedDailyCoalescing() { yield schedulerTickCallback(); // Wait for the daily ping. - let request = yield gRequestIterator.next(); - let dailyPing = decodeRequestPayload(request); + let dailyPing = yield PingServer.promiseNextPing(); Assert.equal(dailyPing.payload.info.reason, REASON_DAILY); // Check that an aborted session ping was also written to disk. @@ -1492,7 +1443,7 @@ add_task(function* test_schedulerComputerSleep() { const ABORTED_FILE = OS.Path.join(DATAREPORTING_PATH, ABORTED_PING_FILE_NAME); - gRequestIterator = Iterator(new Request()); + PingServer.clearRequests(); // Remove any aborted-session ping from the previous tests. yield OS.File.removeDir(DATAREPORTING_PATH, { ignoreAbsent: true }); @@ -1511,8 +1462,7 @@ add_task(function* test_schedulerComputerSleep() { // Execute one scheduler tick. yield schedulerTickCallback(); - let request = yield gRequestIterator.next(); - let dailyPing = decodeRequestPayload(request); + let dailyPing = yield PingServer.promiseNextPing(); Assert.equal(dailyPing.payload.info.reason, REASON_DAILY); Assert.ok((yield OS.File.exists(ABORTED_FILE)), @@ -1535,7 +1485,7 @@ add_task(function* test_schedulerEnvironmentReschedules() { ]); yield clearPendingPings(); - gRequestIterator = Iterator(new Request()); + PingServer.clearRequests(); // Set a fake current date and start Telemetry. let nowDate = new Date(2060, 10, 18, 0, 0, 0); @@ -1553,10 +1503,10 @@ add_task(function* test_schedulerEnvironmentReschedules() { Preferences.set(PREF_TEST, 1); // Wait for the environment-changed ping. - yield gRequestIterator.next(); + yield PingServer.promiseNextPing(); // We don't expect to receive any daily ping in this test, so assert if we do. - registerPingHandler((req, res) => { + PingServer.registerPingHandler((req, res) => { Assert.ok(false, "No ping should be sent/received in this test."); }); @@ -1580,7 +1530,7 @@ add_task(function* test_schedulerNothingDue() { yield clearPendingPings(); // We don't expect to receive any ping in this test, so assert if we do. - registerPingHandler((req, res) => { + PingServer.registerPingHandler((req, res) => { Assert.ok(false, "No ping should be sent/received in this test."); }); @@ -1603,6 +1553,7 @@ add_task(function* test_schedulerNothingDue() { Assert.ok(!(yield OS.File.exists(ABORTED_FILE))); yield TelemetrySession.shutdown(); + PingServer.resetPingHandler(); }); add_task(function* test_pingExtendedStats() { @@ -1615,12 +1566,11 @@ add_task(function* test_pingExtendedStats() { Telemetry.canRecordExtended = false; yield clearPendingPings(); - gRequestIterator = Iterator(new Request()); + PingServer.clearRequests(); yield TelemetrySession.reset(); yield sendPing(); - let request = yield gRequestIterator.next(); - let ping = decodeRequestPayload(request); + let ping = yield PingServer.promiseNextPing(); checkPingFormat(ping, PING_TYPE_MAIN, true, true); // Check that the payload does not contain extended statistics fields. @@ -1645,8 +1595,7 @@ add_task(function* test_pingExtendedStats() { // Send a new ping that should contain the extended data. yield TelemetrySession.reset(); yield sendPing(); - request = yield gRequestIterator.next(); - ping = decodeRequestPayload(request); + ping = yield PingServer.promiseNextPing(); checkPingFormat(ping, PING_TYPE_MAIN, true, true); // Check that the payload now contains extended statistics fields. @@ -1679,7 +1628,7 @@ add_task(function* test_schedulerUserIdle() { }, () => {}); yield TelemetrySession.reset(); yield clearPendingPings(); - gRequestIterator = Iterator(new Request()); + PingServer.clearRequests(); // When not idle, the scheduler should have a 5 minutes tick interval. Assert.equal(schedulerTimeout, SCHEDULER_TICK_INTERVAL_MS); @@ -1707,31 +1656,6 @@ add_task(function* test_schedulerUserIdle() { }); add_task(function* stopServer(){ - gHttpServer.stop(do_test_finished); + yield PingServer.stop(); + do_test_finished(); }); - -// An iterable sequence of http requests -function Request() { - let defers = []; - let current = 0; - - function RequestIterator() {} - - // Returns a promise that resolves to the next http request - RequestIterator.prototype.next = function() { - let deferred = defers[current++]; - return deferred.promise; - } - - this.__iterator__ = function(){ - return new RequestIterator(); - } - - registerPingHandler((request, response) => { - let deferred = defers[defers.length - 1]; - defers.push(Promise.defer()); - deferred.resolve(request); - }); - - defers.push(Promise.defer()); -} diff --git a/toolkit/components/telemetry/tests/unit/xpcshell.ini b/toolkit/components/telemetry/tests/unit/xpcshell.ini index 219cda4ab2c3..54600c0674a7 100644 --- a/toolkit/components/telemetry/tests/unit/xpcshell.ini +++ b/toolkit/components/telemetry/tests/unit/xpcshell.ini @@ -50,5 +50,6 @@ skip-if = os == "android" # Disabled due to intermittent orange on Android skip-if = android_version == "18" [test_ThreadHangStats.js] run-sequentially = Bug 1046307, test can fail intermittently when CPU load is high +[test_TelemetrySend.js] [test_ChildHistograms.js] skip-if = os == "android"