From 3635aa6f6f5868cf21e59e39c83c23cda2525b56 Mon Sep 17 00:00:00 2001 From: Mike Conley Date: Fri, 6 Dec 2013 16:37:52 -0500 Subject: [PATCH] Bug 863872 - If we have overdue TelemetryPings, try to send them all. r=nfroyd, feedback=irving. --- .../components/telemetry/TelemetryFile.jsm | 75 ++++- toolkit/components/telemetry/TelemetryPing.js | 26 +- .../tests/unit/test_TelemetryPing.js | 4 +- .../tests/unit/test_TelemetrySendOldPings.js | 265 ++++++++++++++++++ .../telemetry/tests/unit/xpcshell.ini | 2 + 5 files changed, 353 insertions(+), 19 deletions(-) create mode 100644 toolkit/components/telemetry/tests/unit/test_TelemetrySendOldPings.js diff --git a/toolkit/components/telemetry/TelemetryFile.jsm b/toolkit/components/telemetry/TelemetryFile.jsm index 7a21d5c2fd4e..8db9eb815b58 100644 --- a/toolkit/components/telemetry/TelemetryFile.jsm +++ b/toolkit/components/telemetry/TelemetryFile.jsm @@ -22,8 +22,13 @@ const PR_EXCL = 0x80; const RW_OWNER = parseInt("0600", 8); const RWX_OWNER = parseInt("0700", 8); -// Delete ping files that have been lying around for longer than this. -const MAX_PING_FILE_AGE = 7 * 24 * 60 * 60 * 1000; // 1 week +// 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 + +// 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 // The number of outstanding saved pings that we have issued loading // requests for. @@ -32,6 +37,14 @@ let pingsLoaded = 0; // The number of those requests that have actually completed. let pingLoadsCompleted = 0; +// The number of pings that we have destroyed due to being older +// than MAX_PING_FILE_AGE. +let pingsDiscarded = 0; + +// The number of pings that are older than OVERDUE_PING_FILE_AGE +// but younger than MAX_PING_FILE_AGE. +let pingsOverdue = 0; + // If |true|, send notifications "telemetry-test-save-complete" // and "telemetry-test-load-complete" once save/load is complete. let shouldNotifyUponSave = false; @@ -41,6 +54,14 @@ let pendingPings = []; this.TelemetryFile = { + get MAX_PING_FILE_AGE() { + return MAX_PING_FILE_AGE; + }, + + get OVERDUE_PING_FILE_AGE() { + return OVERDUE_PING_FILE_AGE; + }, + /** * Save a single ping to a file. * @@ -142,7 +163,7 @@ this.TelemetryFile = { * ping. It is passed |true| in case of success, |false| in case of * format error. */ - loadSavedPings: function(sync, onLoad = null) { + loadSavedPings: function(sync, onLoad = null, onDone = null) { let directory = ensurePingDirectory(); let entries = directory.directoryEntries .QueryInterface(Ci.nsIDirectoryEnumerator); @@ -150,7 +171,7 @@ this.TelemetryFile = { pingLoadsCompleted = 0; try { while (entries.hasMoreElements()) { - this.loadHistograms(entries.nextFile, sync, onLoad); + this.loadHistograms(entries.nextFile, sync, onLoad, onDone); } } finally { entries.close(); @@ -169,20 +190,26 @@ this.TelemetryFile = { * ping. It is passed |true| in case of success, |false| in case of * format error. */ - loadHistograms: function loadHistograms(file, sync, onLoad = null) { - let now = new Date(); + loadHistograms: function loadHistograms(file, sync, onLoad = null, onDone = null) { + let now = Date.now(); if (now - file.lastModifiedTime > MAX_PING_FILE_AGE) { // We haven't had much luck in sending this file; delete it. file.remove(true); + pingsDiscarded++; return; } + // This file is a bit stale, and overdue for sending. + if (now - file.lastModifiedTime > OVERDUE_PING_FILE_AGE) { + pingsOverdue++; + } + pingsLoaded++; if (sync) { let stream = Cc["@mozilla.org/network/file-input-stream;1"] .createInstance(Ci.nsIFileInputStream); stream.init(file, -1, -1, 0); - addToPendingPings(file, stream, onLoad); + addToPendingPings(file, stream, onLoad, onDone); } else { let channel = NetUtil.newChannel(file); channel.contentType = "application/json"; @@ -191,7 +218,7 @@ this.TelemetryFile = { if (!Components.isSuccessCode(result)) { return; } - addToPendingPings(file, stream, onLoad); + addToPendingPings(file, stream, onLoad, onDone); }).bind(this)); } }, @@ -203,6 +230,22 @@ this.TelemetryFile = { return pingsLoaded; }, + /** + * The number of pings loaded that are older than OVERDUE_PING_FILE_AGE + * but younger than MAX_PING_FILE_AGE. + */ + get pingsOverdue() { + return pingsOverdue; + }, + + /** + * The number of pings that we just tossed out for being older than + * MAX_PING_FILE_AGE. + */ + get pingsDiscarded() { + return pingsDiscarded; + }, + /** * Iterate destructively through the pending pings. * @@ -249,7 +292,7 @@ function ensurePingDirectory() { return directory; }; -function addToPendingPings(file, stream, onLoad) { +function addToPendingPings(file, stream, onLoad, onDone) { let success = false; try { @@ -263,19 +306,25 @@ function addToPendingPings(file, stream, onLoad) { } pingLoadsCompleted++; pendingPings.push(ping); - if (shouldNotifyUponSave && - pingLoadsCompleted == pingsLoaded) { - Services.obs.notifyObservers(null, "telemetry-test-load-complete", null); - } success = true; } catch (e) { // An error reading the file, or an error parsing the contents. stream.close(); // close is idempotent. file.remove(true); // FIXME: Should be false, isn't it? } + if (onLoad) { onLoad(success); } + + if (pingLoadsCompleted == pingsLoaded) { + if (onDone) { + onDone(); + } + if (shouldNotifyUponSave) { + Services.obs.notifyObservers(null, "telemetry-test-load-complete", null); + } + } }; function finishTelemetrySave(ok, stream) { diff --git a/toolkit/components/telemetry/TelemetryPing.js b/toolkit/components/telemetry/TelemetryPing.js index b96bbde06be2..ed7cc2f26f01 100644 --- a/toolkit/components/telemetry/TelemetryPing.js +++ b/toolkit/components/telemetry/TelemetryPing.js @@ -39,6 +39,8 @@ const PREF_PREVIOUS_BUILDID = PREF_BRANCH + "previousBuildID"; const TELEMETRY_INTERVAL = 60000; // Delay before intializing telemetry (ms) const TELEMETRY_DELAY = 60000; +// Delay before initializing telemetry if we're testing (ms) +const TELEMETRY_TEST_DELAY = 100; // Seconds of idle time before pinging. // On idle-daily a gather-telemetry notification is fired, during it probes can @@ -218,6 +220,9 @@ TelemetryPing.prototype = { ret.savedPings = TelemetryFile.pingsLoaded; } + ret.pingsOverdue = TelemetryFile.pingsOverdue; + ret.pingsDiscarded = TelemetryFile.pingsDiscarded; + return ret; }, @@ -599,7 +604,9 @@ TelemetryPing.prototype = { popPayloads: function popPayloads(reason) { function payloadIter() { - yield this.getSessionPayloadAndSlug(reason); + if (reason != "overdue-flush") { + yield this.getSessionPayloadAndSlug(reason); + } let iterator = TelemetryFile.popPendingPings(reason); for (let data of iterator) { yield data; @@ -761,7 +768,7 @@ TelemetryPing.prototype = { /** * Initializes telemetry within a timer. If there is no PREF_SERVER set, don't turn on telemetry. */ - setup: function setup() { + setup: function setup(aTesting) { // Initialize some probes that are kept in their own modules this._thirdPartyCookies = new ThirdPartyCookieProbe(); this._thirdPartyCookies.init(); @@ -824,7 +831,17 @@ TelemetryPing.prototype = { { let success_histogram = Telemetry.getHistogramById("READ_SAVED_PING_SUCCESS"); success_histogram.add(success); - })); + }), () => + { + // If we have any TelemetryPings lying around, we'll be aggressive + // and try to send them all off ASAP. + if (TelemetryFile.pingsOverdue > 0) { + // It doesn't really matter what we pass to this.send as a reason, + // since it's never sent to the server. All that this.send does with + // the reason is check to make sure it's not a test-ping. + this.send("overdue-flush", this._server); + } + }); this.attachObservers(); this.gatherMemory(); @@ -832,7 +849,8 @@ TelemetryPing.prototype = { }); delete this._timer; } - this._timer.initWithCallback(timerCallback.bind(this), TELEMETRY_DELAY, + this._timer.initWithCallback(timerCallback.bind(this), + aTesting ? TELEMETRY_TEST_DELAY : TELEMETRY_DELAY, Ci.nsITimer.TYPE_ONE_SHOT); }, diff --git a/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js b/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js index c859b779c947..06d9292719cd 100644 --- a/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js +++ b/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js @@ -142,7 +142,7 @@ function decodeRequestPayload(request) { let observer = { buffer: "", onStreamComplete: function(loader, context, status, length, result) { - this.buffer = String.fromCharCode.apply(this, result); + this.buffer = String.fromCharCode.apply(this, result); } }; @@ -363,7 +363,7 @@ function runOldPingFileTest() { do_check_true(histogramsFile.exists()); let mtime = histogramsFile.lastModifiedTime; - histogramsFile.lastModifiedTime = mtime - 8 * 24 * 60 * 60 * 1000; // 8 days. + histogramsFile.lastModifiedTime = mtime - 14 * 24 * 60 * 60 * 1000; // 14 days. TelemetryPing.testLoadHistograms(histogramsFile, true); do_check_false(histogramsFile.exists()); } diff --git a/toolkit/components/telemetry/tests/unit/test_TelemetrySendOldPings.js b/toolkit/components/telemetry/tests/unit/test_TelemetrySendOldPings.js new file mode 100644 index 000000000000..0ba9707d8f53 --- /dev/null +++ b/toolkit/components/telemetry/tests/unit/test_TelemetrySendOldPings.js @@ -0,0 +1,265 @@ +/* Any copyright is dedicated to the Public Domain. + http://creativecommons.org/publicdomain/zero/1.0/ + +/** + * This test case populates the profile with some fake stored + * pings, and checks that: + * + * 1) Pings that are considered "expired" are deleted and never sent. + * 2) Pings that are considered "overdue" trigger a send of all + * overdue and recent pings. + */ + +Components.utils.import("resource://gre/modules/Services.jsm"); + +// Get the TelemetryPing definitions directly so we can test it without going through xpcom. +// That gives us Cc, Ci, Cr and Cu, as well as a number of consts like PREF_ENABLED, +// and PREF_SERVER. +Services.scriptloader.loadSubScript("resource://gre/components/TelemetryPing.js"); + +Cu.import("resource://testing-common/httpd.js"); +Cu.import("resource://gre/modules/Promise.jsm"); +Cu.import("resource://gre/modules/TelemetryFile.jsm"); + +// We increment TelemetryFile's MAX_PING_FILE_AGE and +// OVERDUE_PING_FILE_AGE by 1ms so that our test pings exceed +// those points in time. +const EXPIRED_PING_FILE_AGE = TelemetryFile.MAX_PING_FILE_AGE + 1; +const OVERDUE_PING_FILE_AGE = TelemetryFile.OVERDUE_PING_FILE_AGE + 1; + +const PING_SAVE_FOLDER = "saved-telemetry-pings"; +const PING_TIMEOUT_LENGTH = 1500; +const EXPIRED_PINGS = 5; +const OVERDUE_PINGS = 6; +const RECENT_PINGS = 4; + +const TOTAL_EXPECTED_PINGS = OVERDUE_PINGS + RECENT_PINGS; + +let gHttpServer = new HttpServer(); +let gCreatedPings = 0; +let gSeenPings = 0; + +/** + * Creates some TelemetryPings for the current session and + * saves them to disk. Each ping gets a unique ID slug based on + * an incrementor. + * + * @param aNum the number of pings to create. + * @param aAge the age in milliseconds to offset from now. A value + * of 10 would make the ping 10ms older than now, for + * example. + * @returns an Array with the created pings. + */ +function createSavedPings(aNum, aAge) { + // Create a TelemetryPing service that we can generate payloads from. + // Luckily, the TelemetryPing constructor does nothing that we need to + // clean up. + let pingService = new TelemetryPing(); + let pings = []; + let age = Date.now() - aAge; + for (let i = 0; i < aNum; ++i) { + let payload = pingService.getPayload(); + let ping = { slug: "test-ping-" + gCreatedPings, reason: "test", payload: payload }; + TelemetryFile.savePing(ping); + if (aAge) { + // savePing writes to the file synchronously, so we're good to + // modify the lastModifedTime now. + let file = getSaveFileForPing(ping); + file.lastModifiedTime = age; + } + gCreatedPings++; + pings.push(ping); + } + return pings; +} + +/** + * Deletes locally saved pings in aPings if they + * exist. + * + * @param aPings an Array of pings to delete. + */ +function clearPings(aPings) { + for (let ping of aPings) { + let file = getSaveFileForPing(ping); + if (file.exists()) { + file.remove(false); + } + } +} + +/** + * Returns a handle for the file that aPing should be + * stored in locally. + * + * @returns nsILocalFile + */ +function getSaveFileForPing(aPing) { + let file = Services.dirsvc.get("ProfD", Ci.nsILocalFile).clone(); + file.append(PING_SAVE_FOLDER); + file.append(aPing.slug); + return file; +} + +/** + * Wait for PING_TIMEOUT_LENGTH ms, and make sure we didn't receive + * TelemetryPings in that time. + * + * @returns Promise + */ +function assertReceivedNoPings() { + let deferred = Promise.defer(); + + do_timeout(PING_TIMEOUT_LENGTH, function() { + if (gSeenPings > 0) { + deferred.reject(); + } else { + deferred.resolve(); + } + }); + + return deferred.promise; +} + +/** + * Returns a Promise that rejects if the number of TelemetryPings + * received by the HttpServer is not equal to aExpectedNum. + * + * @param aExpectedNum the number of pings we expect to receive. + * @returns Promise + */ +function assertReceivedPings(aExpectedNum) { + let deferred = Promise.defer(); + + do_timeout(PING_TIMEOUT_LENGTH, function() { + if (gSeenPings == aExpectedNum) { + deferred.resolve(); + } else { + deferred.reject("Saw " + gSeenPings + " TelemetryPings, " + + "but expected " + aExpectedNum); + } + }) + + return deferred.promise; +} + +/** + * Throws if any pings in aPings is saved locally. + * + * @param aPings an Array of pings to check. + */ +function assertNotSaved(aPings) { + let saved = 0; + for (let ping of aPings) { + let file = getSaveFileForPing(ping); + if (file.exists()) { + saved++; + } + } + if (saved > 0) { + do_throw("Found " + saved + " unexpected saved pings."); + } +} + +/** + * Our handler function for the HttpServer that simply + * increments the gSeenPings global when it successfully + * receives and decodes a TelemetryPing payload. + * + * @param aRequest the HTTP request sent from HttpServer. + */ +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; +} + +/** + * Teardown a TelemetryPing instance and clear out any pending + * pings to put as back in the starting state. + */ +function resetTelemetry(aPingService) { + aPingService.uninstall(); + // Quick and dirty way to clear TelemetryFile's pendingPings + // collection, and put it back in its initial state. + let gen = TelemetryFile.popPendingPings(); + for (let item of gen) {}; +} + +/** + * Creates and returns a TelemetryPing instance in "testing" + * mode. + */ +function startTelemetry() { + let service = new TelemetryPing(); + service.setup(true); + return service; +} + +function run_test() { + gHttpServer.registerPrefixHandler("/submit/telemetry/", pingHandler); + gHttpServer.start(-1); + do_get_profile(); + Services.prefs.setBoolPref(PREF_ENABLED, true); + Services.prefs.setCharPref(PREF_SERVER, + "http://localhost:" + gHttpServer.identity.primaryPort); + run_next_test(); +} + +/** + * Test that pings that are considered too old are just chucked out + * immediately and never sent. + */ +add_task(function test_expired_pings_are_deleted() { + let expiredPings = createSavedPings(EXPIRED_PINGS, EXPIRED_PING_FILE_AGE); + let pingService = startTelemetry(); + yield assertReceivedNoPings(); + assertNotSaved(expiredPings); + resetTelemetry(pingService); +}) + +/** + * Test that really recent pings are not sent on Telemetry initialization. + */ +add_task(function test_recent_pings_not_sent() { + let recentPings = createSavedPings(RECENT_PINGS); + let pingService = startTelemetry(); + yield assertReceivedNoPings(); + resetTelemetry(pingService); + clearPings(recentPings); +}); + +/** + * Create some recent, expired and overdue pings. The overdue pings should + * trigger a send of all recent and overdue pings, but the expired pings + * should just be deleted. + */ +add_task(function test_overdue_pings_trigger_send() { + let recentPings = createSavedPings(RECENT_PINGS); + let expiredPings = createSavedPings(EXPIRED_PINGS, EXPIRED_PING_FILE_AGE); + let overduePings = createSavedPings(OVERDUE_PINGS, OVERDUE_PING_FILE_AGE); + + let pingService = startTelemetry(); + yield assertReceivedPings(TOTAL_EXPECTED_PINGS); + + assertNotSaved(recentPings); + assertNotSaved(expiredPings); + assertNotSaved(overduePings); + resetTelemetry(pingService); +}) + +add_task(function teardown() { + yield stopHttpServer(); +}); diff --git a/toolkit/components/telemetry/tests/unit/xpcshell.ini b/toolkit/components/telemetry/tests/unit/xpcshell.ini index 339219fedcdc..5a0d1b138cd3 100644 --- a/toolkit/components/telemetry/tests/unit/xpcshell.ini +++ b/toolkit/components/telemetry/tests/unit/xpcshell.ini @@ -12,3 +12,5 @@ tail = [test_TelemetryStopwatch.js] [test_TelemetryPingBuildID.js] [test_ThirdPartyCookieProbe.js] +[test_TelemetrySendOldPings.js] +skip-if = debug == true