Bug 863872 - If we have overdue TelemetryPings, try to send them all. r=nfroyd, feedback=irving.
☠☠ backed out by 769e5d448b1e ☠ ☠
authorMike Conley <mconley@mozilla.com>
Fri, 06 Dec 2013 16:37:52 -0500
changeset 174983 16628db76c3c6522471e998c9ef4ec49203ec80e
parent 174982 fac17c3d3efd6a8f264bb6678ca2af75105afc41
child 174984 6cc28fece8bfb6595c022ba995f92fc543b8d924
push id445
push userffxbld
push dateMon, 10 Mar 2014 22:05:19 +0000
treeherdermozilla-release@dc38b741b04e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersnfroyd
bugs863872
milestone28.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 863872 - If we have overdue TelemetryPings, try to send them all. r=nfroyd, feedback=irving.
toolkit/components/telemetry/TelemetryFile.jsm
toolkit/components/telemetry/TelemetryPing.js
toolkit/components/telemetry/tests/unit/test_TelemetryPing.js
toolkit/components/telemetry/tests/unit/test_TelemetrySendOldPings.js
toolkit/components/telemetry/tests/unit/xpcshell.ini
--- a/toolkit/components/telemetry/TelemetryFile.jsm
+++ b/toolkit/components/telemetry/TelemetryFile.jsm
@@ -17,35 +17,56 @@ let {Services, Deprecated, NetUtil} = im
 // Constants from prio.h for nsIFileOutputStream.init
 const PR_WRONLY = 0x2;
 const PR_CREATE_FILE = 0x8;
 const PR_TRUNCATE = 0x20;
 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.
 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;
 
 // Data that has neither been saved nor sent by ping
 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.
    *
    * @param {object} ping The content of the ping to save.
    * @param {nsIFile} file The destination file.
    * @param {bool} sync If |true|, write synchronously. Deprecated.
    * This argument should be |false|.
    * @param {bool} overwrite If |true|, the file will be overwritten
@@ -137,25 +158,25 @@ this.TelemetryFile = {
    * Once loaded, the saved pings can be accessed (destructively only)
    * through |popPendingPings|.
    *
    * @param {bool} sync If |true|, loading takes place synchronously.
    * @param {function*} onLoad A function called upon loading of each
    * 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);
     pingsLoaded = 0;
     pingLoadsCompleted = 0;
     try {
       while (entries.hasMoreElements()) {
-        this.loadHistograms(entries.nextFile, sync, onLoad);
+        this.loadHistograms(entries.nextFile, sync, onLoad, onDone);
       }
     } finally {
       entries.close();
     }
   },
 
   /**
    * Load the histograms from a file.
@@ -164,51 +185,73 @@ this.TelemetryFile = {
    * through |popPendingPings|.
    *
    * @param {nsIFile} file The file to load.
    * @param {bool} sync If |true|, loading takes place synchronously.
    * @param {function*} onLoad A function called upon loading of the
    * 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";
 
       NetUtil.asyncFetch(channel, (function(stream, result) {
         if (!Components.isSuccessCode(result)) {
           return;
         }
-        addToPendingPings(file, stream, onLoad);
+        addToPendingPings(file, stream, onLoad, onDone);
       }).bind(this));
     }
   },
 
   /**
    * The number of pings loaded since the beginning of time.
    */
   get pingsLoaded() {
     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.
    *
    * @return {iterator}
    */
   popPendingPings: function(reason) {
     while (pendingPings.length > 0) {
       let data = pendingPings.pop();
       // Send persisted pings to the test URL too.
@@ -244,43 +287,49 @@ function ensurePingDirectory() {
   try {
     directory.create(Ci.nsIFile.DIRECTORY_TYPE, RWX_OWNER);
   } catch (e) {
     // Already exists, just ignore this.
   }
   return directory;
 };
 
-function addToPendingPings(file, stream, onLoad) {
+function addToPendingPings(file, stream, onLoad, onDone) {
   let success = false;
 
   try {
     let string = NetUtil.readInputStreamToString(stream, stream.available(),
       { charset: "UTF-8" });
     stream.close();
     let ping = JSON.parse(string);
     // The ping's payload used to be stringified JSON.  Deal with that.
     if (typeof(ping.payload) == "string") {
       ping.payload = JSON.parse(ping.payload);
     }
     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) {
   stream.close();
   if (shouldNotifyUponSave && ok) {
     Services.obs.notifyObservers(null, "telemetry-test-save-complete", null);
   }
 };
--- a/toolkit/components/telemetry/TelemetryPing.js
+++ b/toolkit/components/telemetry/TelemetryPing.js
@@ -34,16 +34,18 @@ const PREF_ENABLED = PREF_BRANCH + "enab
 const PREF_ENABLED = PREF_BRANCH + "enabled";
 #endif
 const PREF_PREVIOUS_BUILDID = PREF_BRANCH + "previousBuildID";
 
 // Do not gather data more than once a minute
 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
 // start asynchronous tasks to gather data.  On the next idle the data is sent.
 const IDLE_TIMEOUT_SECONDS = 5 * 60;
 
 var gLastMemoryPoll = null;
 
@@ -211,16 +213,18 @@ TelemetryPing.prototype = {
 
     let hasPingBeenSent = false;
     try {
       hasPingBeenSent = Telemetry.getHistogramById("TELEMETRY_SUCCESS").snapshot().sum > 0;
     } catch(e) {
     }
     if (!forSavedSession || hasPingBeenSent) {
       ret.savedPings = TelemetryFile.pingsLoaded;
+      ret.pingsOverdue = TelemetryFile.pingsOverdue;
+      ret.pingsDiscarded = TelemetryFile.pingsDiscarded;
     }
 
     return ret;
   },
 
   /**
    * When reflecting a histogram into JS, Telemetry hands us an object
    * with the following properties:
@@ -756,17 +760,17 @@ TelemetryPing.prototype = {
       idleService.removeIdleObserver(this, IDLE_TIMEOUT_SECONDS);
       this._isIdleObserver = false;
     }
   },
 
   /**
    * 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();
 
     // Record old value and update build ID preference if this is the first
     // run with a new build ID.
     let previousBuildID = undefined;
     try {
@@ -819,25 +823,36 @@ TelemetryPing.prototype = {
     // footprint and other numbers would be too optimistic.
     this._timer = Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
     function timerCallback() {
       this._initialized = true;
       TelemetryFile.loadSavedPings(false, (success =>
         {
           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();
 
       Telemetry.asyncFetchTelemetryData(function () {
       });
       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);
   },
 
   testLoadHistograms: function testLoadHistograms(file, sync) {
     TelemetryFile.testLoadHistograms(file, sync, (success =>
         {
           let success_histogram = Telemetry.getHistogramById("READ_SAVED_PING_SUCCESS");
           success_histogram.add(success);
--- a/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js
+++ b/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js
@@ -137,17 +137,17 @@ function decodeRequestPayload(request) {
   let s = request.bodyInputStream;
   let payload = null;
   let decoder = Cc["@mozilla.org/dom/json;1"].createInstance(Ci.nsIJSON)
 
   if (request.getHeader("content-encoding") == "gzip") {
     let observer = {
       buffer: "",
       onStreamComplete: function(loader, context, status, length, result) {
-	this.buffer = String.fromCharCode.apply(this, result);
+        this.buffer = String.fromCharCode.apply(this, result);
       }
     };
 
     let scs = Cc["@mozilla.org/streamConverters;1"]
               .getService(Ci.nsIStreamConverterService);
     let listener = Cc["@mozilla.org/network/stream-loader;1"]
                   .createInstance(Ci.nsIStreamLoader);
     listener.init(observer);
@@ -358,17 +358,17 @@ function runInvalidJSONTest() {
 }
 
 function runOldPingFileTest() {
   let histogramsFile = getSavedHistogramsFile("old-histograms.dat");
   TelemetryPing.saveHistograms(histogramsFile, true);
   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());
 }
 
 function dummyTheme(id) {
   return {
     id: id,
     name: Math.random().toString(),
new file mode 100644
--- /dev/null
+++ b/toolkit/components/telemetry/tests/unit/test_TelemetrySendOldPings.js
@@ -0,0 +1,268 @@
+/* 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;
+
+// The +1 at the end of TOTAL_EXPECTED_PINGS is because when TelemetryPing
+// sends off all of the saved pings, it also sends a ping for the current
+// session.
+const TOTAL_EXPECTED_PINGS = OVERDUE_PINGS + RECENT_PINGS + 1;
+
+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();
+});
\ No newline at end of file
--- a/toolkit/components/telemetry/tests/unit/xpcshell.ini
+++ b/toolkit/components/telemetry/tests/unit/xpcshell.ini
@@ -7,8 +7,9 @@ tail =
 [test_TelemetryLockCount.js]
 [test_TelemetryPing.js]
 # Bug 676989: test fails consistently on Android
 # fail-if = os == "android"
 [test_TelemetryPing_idle.js]
 [test_TelemetryStopwatch.js]
 [test_TelemetryPingBuildID.js]
 [test_ThirdPartyCookieProbe.js]
+[test_TelemetrySendOldPings.js]