Bug 863872 - If we have overdue TelemetryPings, try to send them all. r=nfroyd, feedback=irving.

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) {

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;
   },
 
@@ -598,7 +603,9 @@ TelemetryPing.prototype = {
 
   popPayloads: function popPayloads(reason) {
     function payloadIter() {
+      if (reason != "overdue-flush") {
         yield this.getSessionPayloadAndSlug(reason);
+      }
       let iterator = TelemetryFile.popPendingPings(reason);
       for (let data of iterator) {
         yield data;
@@ -760,7 +767,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();
@@ -823,7 +830,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();
 
@@ -831,7 +848,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);
   },
 

toolkit/components/telemetry/tests/unit/test_TelemetryPing.js

@@ -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 + 60000); // 14 days, 1m
   TelemetryPing.testLoadHistograms(histogramsFile, true);
   do_check_false(histogramsFile.exists());
 }

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 = 5000;
+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();
+});

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 || os == "android" # Disabled due to intermittent orange on Android