Bug 899686 - Mock out nsITimer to avoid race condition in tests. r=yoric, a=test-only
authorIrving Reid <irving@mozilla.com>
Fri, 20 Dec 2013 11:44:21 -0500
changeset 167796 842c26f878c55e717228c6b54b62da907257f9d4
parent 167795 072a8ecc163bc066c6fdd2130a88e145625abe40
child 167797 77e29fc57c6b1173acd9c23f56ae31e4299e5cc3
push id428
push userbbajaj@mozilla.com
push dateTue, 28 Jan 2014 00:16:25 +0000
treeherdermozilla-release@cd72a7ff3a75 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersyoric, test-only
bugs899686
milestone27.0
Bug 899686 - Mock out nsITimer to avoid race condition in tests. r=yoric, a=test-only
toolkit/mozapps/extensions/DeferredSave.jsm
toolkit/mozapps/extensions/test/xpcshell/test_DeferredSave.js
--- a/toolkit/mozapps/extensions/DeferredSave.jsm
+++ b/toolkit/mozapps/extensions/DeferredSave.jsm
@@ -6,16 +6,19 @@
 
 const Cu = Components.utils;
 const Cc = Components.classes;
 const Ci = Components.interfaces;
 
 Cu.import("resource://gre/modules/osfile.jsm");
 Cu.import("resource://gre/modules/Promise.jsm");
 
+// Make it possible to mock out timers for testing
+let MakeTimer = () => Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
+
 this.EXPORTED_SYMBOLS = ["DeferredSave"];
 
 // If delay parameter is not provided, default is 50 milliseconds.
 const DEFAULT_SAVE_DELAY_MS = 50;
 
 /**
  * A module to manage deferred, asynchronous writing of data files
  * to disk. Writing is deferred by waiting for a specified delay after
@@ -99,17 +102,17 @@ this.DeferredSave.prototype = {
   // Start the pending timer if data is dirty
   _startTimer: function() {
     if (!this._pending) {
       return;
     }
 
     this.LOG("Starting timer");
     if (!this._timer)
-      this._timer = Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
+      this._timer = MakeTimer();
     this._timer.initWithCallback(() => this._deferredSave(),
                                  this._delay, Ci.nsITimer.TYPE_ONE_SHOT);
   },
 
   /**
    * Mark the current stored data dirty, and schedule a flush to disk
    * @return A Promise<integer> that will be resolved after the data is written to disk;
    *         the promise is resolved with the number of bytes written.
--- a/toolkit/mozapps/extensions/test/xpcshell/test_DeferredSave.js
+++ b/toolkit/mozapps/extensions/test/xpcshell/test_DeferredSave.js
@@ -7,21 +7,21 @@
 
 "use strict";
 
 const testFile = gProfD.clone();
 testFile.append("DeferredSaveTest");
 
 Components.utils.import("resource://gre/modules/Promise.jsm");
 
-let context = Components.utils.import("resource://gre/modules/DeferredSave.jsm", {});
-let DeferredSave = context.DeferredSave;
+let DSContext = Components.utils.import("resource://gre/modules/DeferredSave.jsm", {});
+let DeferredSave = DSContext.DeferredSave;
 
-// Test wrapper to let us do promise/task based testing of DeferredSaveP
-function DeferredSaveTester(aDelay, aDataProvider) {
+// Test wrapper to let us do promise/task based testing of DeferredSave
+function DeferredSaveTester(aDataProvider) {
   let tester = {
     // Deferred for the promise returned by the mock writeAtomic
     waDeferred: null,
 
     // The most recent data "written" by the mock OS.File.writeAtomic
     writtenData: undefined,
 
     dataToSave: "Data to save",
@@ -49,58 +49,124 @@ function DeferredSaveTester(aDelay, aDat
     do_print("default write callback");
     let length = aTester.writtenData.length;
     do_execute_soon(() => aTester.waDeferred.resolve(length));
   }
 
   if (!aDataProvider)
     aDataProvider = () => tester.dataToSave;
 
-  tester.saver = new DeferredSave(testFile.path, aDataProvider, aDelay);
+  tester.saver = new DeferredSave(testFile.path, aDataProvider);
 
   // Install a mock for OS.File.writeAtomic to let us control the async
   // behaviour of the promise
-  context.OS.File.writeAtomic = function mock_writeAtomic(aFile, aData, aOptions) {
+  DSContext.OS.File.writeAtomic = function mock_writeAtomic(aFile, aData, aOptions) {
       do_print("writeAtomic: " + aFile + " data: '" + aData + "', " + aOptions.toSource());
       tester.writtenData = aData;
       tester.waDeferred = Promise.defer();
       tester.writeHandler(tester);
       return tester.waDeferred.promise;
     };
 
   return tester;
 };
 
 /**
+ * Install a mock nsITimer factory that triggers on the next spin of
+ * the event loop after it is scheduled
+ */
+function setQuickMockTimer() {
+  let quickTimer = {
+    initWithCallback: function(aFunction, aDelay, aType) {
+      do_print("Starting quick timer, delay = " + aDelay);
+      do_execute_soon(aFunction);
+    },
+    cancel: function() {
+      do_throw("Attempted to cancel a quickMockTimer");
+    }
+  };
+  DSContext.MakeTimer = () => {
+    do_print("Creating quick timer");
+    return quickTimer;
+  };
+}
+
+/**
+ * Install a mock nsITimer factory in DeferredSave.jsm, returning a promise that resolves
+ * when the client code sets the timer. Test cases can use this to wait for client code to
+ * be ready for a timer event, and then signal the event by calling mockTimer.callback().
+ * This could use some enhancement; clients can re-use the returned timer,
+ * but with this implementation it's not possible for the test to wait for
+ * a second call to initWithCallback() on the re-used timer.
+ * @return Promise{mockTimer} that resolves when initWithCallback()
+ *         is called
+ */
+function setPromiseMockTimer() {
+  let waiter = Promise.defer();
+  let mockTimer = {
+    callback: null,
+    delay: null,
+    type: null,
+    isCancelled: false,
+
+    initWithCallback: function(aFunction, aDelay, aType) {
+      do_print("Starting timer, delay = " + aDelay);
+      this.callback = aFunction;
+      this.delay = aDelay;
+      this.type = aType;
+      // cancelled timers can be re-used
+      this.isCancelled = false;
+      waiter.resolve(this);
+    },
+    cancel: function() {
+      do_print("Cancelled mock timer");
+      this.callback = null;
+      this.delay = null;
+      this.type = null;
+      this.isCancelled = true;
+      // If initWithCallback was never called, resolve to let tests check for cancel
+      waiter.resolve(this);
+    }
+  };
+  DSContext.MakeTimer = () => {
+    do_print("Creating mock timer");
+    return mockTimer;
+  };
+  return waiter.promise;
+}
+
+/**
  * Return a Promise<null> that resolves after the specified number of milliseconds
  */
 function delay(aDelayMS) {
   let deferred = Promise.defer();
   do_timeout(aDelayMS, () => deferred.resolve(null));
   return deferred.promise;
 }
 
 function run_test() {
   run_next_test();
 }
 
 // Modify set data once, ask for save, make sure it saves cleanly
 add_task(function test_basic_save_succeeds() {
-  let tester = DeferredSaveTester(1);
+  setQuickMockTimer();
+  let tester = DeferredSaveTester();
   let data = "Test 1 Data";
 
   yield tester.save(data);
   do_check_eq(tester.writtenData, data);
   do_check_eq(1, tester.saver.totalSaves);
 });
 
 // Two saves called during the same event loop, both with callbacks
 // Make sure we save only the second version of the data
 add_task(function test_two_saves() {
-  let tester = DeferredSaveTester(1);
+  setQuickMockTimer();
+  let tester = DeferredSaveTester();
   let firstCallback_happened = false;
   let firstData = "Test first save";
   let secondData = "Test second save";
 
   // first save should not resolve until after the second one is called,
   // so we can't just yield this promise
   tester.save(firstData).then(count => {
     do_check_eq(secondData, tester.writtenData);
@@ -112,49 +178,60 @@ add_task(function test_two_saves() {
   do_check_true(firstCallback_happened);
   do_check_eq(secondData, tester.writtenData);
   do_check_eq(1, tester.saver.totalSaves);
 });
 
 // Two saves called with a delay in between, both with callbacks
 // Make sure we save the second version of the data
 add_task(function test_two_saves_delay() {
-  let tester = DeferredSaveTester(50);
+  let timerPromise = setPromiseMockTimer();
+  let tester = DeferredSaveTester();
   let firstCallback_happened = false;
   let delayDone = false;
 
   let firstData = "First data to save with delay";
   let secondData = "Modified data to save with delay";
 
   tester.save(firstData).then(count => {
     do_check_false(firstCallback_happened);
     do_check_true(delayDone);
     do_check_eq(secondData, tester.writtenData);
     firstCallback_happened = true;
   }, do_report_unexpected_exception);
 
-  yield delay(5);
+  // Wait a short time to let async events possibly spawned by the
+  // first tester.save() to run
+  yield delay(2);
   delayDone = true;
-  yield tester.save(secondData);
+  // request to save modified data
+  let saving = tester.save(secondData);
+  // Yield to wait for client code to set the timer
+  let activeTimer = yield timerPromise;
+  // and then trigger it
+  activeTimer.callback();
+  // now wait for the DeferredSave to finish saving
+  yield saving;
   do_check_true(firstCallback_happened);
   do_check_eq(secondData, tester.writtenData);
   do_check_eq(1, tester.saver.totalSaves);
   do_check_eq(0, tester.saver.overlappedSaves);
 });
 
 // Test case where OS.File immediately reports an error when the write begins
 // Also check that the "error" getter correctly returns the error
 // Then do a write that succeeds, and make sure the error is cleared
 add_task(function test_error_immediate() {
-  let tester = DeferredSaveTester(1);
+  let tester = DeferredSaveTester();
   let testError = new Error("Forced failure");
   function writeFail(aTester) {
     aTester.waDeferred.reject(testError);
   }
 
+  setQuickMockTimer();
   yield tester.save("test_error_immediate", writeFail).then(
     count => do_throw("Did not get expected error"),
     error => do_check_eq(testError.message, error.message)
     );
   do_check_eq(testError, tester.lastError);
 
   // This write should succeed and clear the error
   yield tester.save("test_error_immediate succeeds");
@@ -162,28 +239,29 @@ add_task(function test_error_immediate()
   // The failed save attempt counts in our total
   do_check_eq(2, tester.saver.totalSaves);
 });
 
 // Save one set of changes, then while the write is in progress, modify the
 // data two more times. Test that we re-write the dirty data exactly once
 // after the first write succeeds
 add_task(function dirty_while_writing() {
-  let tester = DeferredSaveTester(1);
+  let tester = DeferredSaveTester();
   let firstData = "First data";
   let secondData = "Second data";
   let thirdData = "Third data";
   let firstCallback_happened = false;
   let secondCallback_happened = false;
   let writeStarted = Promise.defer();
 
   function writeCallback(aTester) {
     writeStarted.resolve(aTester.waDeferred);
   }
 
+  setQuickMockTimer();
   do_print("First save");
   tester.save(firstData, writeCallback).then(
     count => {
       do_check_false(firstCallback_happened);
       do_check_false(secondCallback_happened);
       do_check_eq(tester.writtenData, firstData);
       firstCallback_happened = true;
     }, do_report_unexpected_exception);
@@ -235,35 +313,37 @@ function write_then_disable(aTester) {
   let length = aTester.writtenData.length;
   aTester.writeHandler = disabled_write_callback;
   do_execute_soon(() => aTester.waDeferred.resolve(length));
 }
 
 // Flush tests. First, do an ordinary clean save and then call flush;
 // there should not be another save
 add_task(function flush_after_save() {
-  let tester = DeferredSaveTester(1);
+  setQuickMockTimer();
+  let tester = DeferredSaveTester();
   let dataToSave = "Flush after save";
 
   yield tester.save(dataToSave);
   yield tester.flush(disabled_write_callback);
   do_check_eq(1, tester.saver.totalSaves);
 });
 
 // Flush while a write is in progress, but the in-memory data is clean
 add_task(function flush_during_write() {
-  let tester = DeferredSaveTester(1);
+  let tester = DeferredSaveTester();
   let dataToSave = "Flush during write";
   let firstCallback_happened = false;
   let writeStarted = Promise.defer();
 
   function writeCallback(aTester) {
     writeStarted.resolve(aTester.waDeferred);
   }
 
+  setQuickMockTimer();
   tester.save(dataToSave, writeCallback).then(
     count => {
       do_check_false(firstCallback_happened);
       firstCallback_happened = true;
     }, do_report_unexpected_exception);
 
   let writer = yield writeStarted.promise;
 
@@ -276,50 +356,55 @@ add_task(function flush_during_write() {
   yield flushing;
   do_check_true(firstCallback_happened);
   do_check_eq(1, tester.saver.totalSaves);
 });
 
 // Flush while dirty but write not in progress
 // The data written should be the value at the time
 // flush() is called, even if it is changed later
-//
-// It would be nice to have a mock for Timer in here, to control
-// when the steps happen, but for now we'll call the flush without
-// going back around the event loop to make sure it happens before
-// the DeferredSave timer goes off
 add_task(function flush_while_dirty() {
-  let tester = DeferredSaveTester(20);
+  let timerPromise = setPromiseMockTimer();
+  let tester = DeferredSaveTester();
   let firstData = "Flush while dirty, valid data";
   let firstCallback_happened = false;
 
   tester.save(firstData, write_then_disable).then(
     count => {
       do_check_false(firstCallback_happened);
       firstCallback_happened = true;
       do_check_eq(tester.writtenData, firstData);
     }, do_report_unexpected_exception);
 
+  // Wait for the timer to be set, but don't trigger it so the write won't start
+  let activeTimer = yield timerPromise;
+
+  let flushing = tester.flush();
+
+  // Make sure the timer was cancelled
+  do_check_true(activeTimer.isCancelled);
+
   // Also make sure that data changed after the flush call
   // (even without a saveChanges() call) doesn't get written
-  let flushing = tester.flush();
   tester.dataToSave = "Flush while dirty, invalid data";
+
   yield flushing;
   do_check_true(firstCallback_happened);
   do_check_eq(tester.writtenData, firstData);
   do_check_eq(1, tester.saver.totalSaves);
 });
 
 // And the grand finale - modify the data, start writing,
 // modify the data again so we're in progress and dirty,
 // then flush, then modify the data again
 // Data for the second write should be taken at the time
 // flush() is called, even if it is modified later
 add_task(function flush_writing_dirty() {
-  let tester = DeferredSaveTester(5);
+  let timerPromise = setPromiseMockTimer();
+  let tester = DeferredSaveTester();
   let firstData = "Flush first pass data";
   let secondData = "Flush second pass data";
   let firstCallback_happened = false;
   let secondCallback_happened = false;
   let writeStarted = Promise.defer();
 
   function writeCallback(aTester) {
     writeStarted.resolve(aTester.waDeferred);
@@ -327,32 +412,36 @@ add_task(function flush_writing_dirty() 
 
   tester.save(firstData, writeCallback).then(
     count => {
       do_check_false(firstCallback_happened);
       do_check_eq(tester.writtenData, firstData);
       firstCallback_happened = true;
     }, do_report_unexpected_exception);
 
+  // Trigger the timer callback as soon as the DeferredSave sets it
+  let activeTimer = yield timerPromise;
+  activeTimer.callback();
   let writer = yield writeStarted.promise;
   // the first write has started
 
   // dirty the data and request another save
   // after the second save completes, there should not be another write
   tester.save(secondData, write_then_disable).then(
     count => {
       do_check_true(firstCallback_happened);
       do_check_false(secondCallback_happened);
       do_check_eq(tester.writtenData, secondData);
       secondCallback_happened = true;
     }, do_report_unexpected_exception);
 
   let flushing = tester.flush(write_then_disable);
+  // Flush should have cancelled our timer
+  do_check_true(activeTimer.isCancelled);
   tester.dataToSave = "Flush, invalid data: changed late";
-  yield delay(1);
   // complete the first write
   writer.resolve(firstData.length);
   // now wait for the second write / flush to complete
   yield flushing;
   do_check_true(firstCallback_happened);
   do_check_true(secondCallback_happened);
   do_check_eq(tester.writtenData, secondData);
   do_check_eq(2, tester.saver.totalSaves);
@@ -370,38 +459,41 @@ function badDataProvider() {
   let err = new Error(badDataError);
   badDataError = "badDataProvider called twice";
   throw err;
 }
 
 // Handle cases where data provider throws
 // First, throws during a normal save
 add_task(function data_throw() {
+  setQuickMockTimer();
   badDataError = expectedDataError;
-  let tester = DeferredSaveTester(1, badDataProvider);
+  let tester = DeferredSaveTester(badDataProvider);
   yield tester.save("data_throw").then(
     count => do_throw("Expected serialization failure"),
     error => do_check_eq(error.message, expectedDataError));
 });
 
 // Now, throws during flush
 add_task(function data_throw_during_flush() {
   badDataError = expectedDataError;
-  let tester = DeferredSaveTester(1, badDataProvider);
+  let tester = DeferredSaveTester(badDataProvider);
   let firstCallback_happened = false;
 
+  setPromiseMockTimer();
   // Write callback should never be called
   tester.save("data_throw_during_flush", disabled_write_callback).then(
     count => do_throw("Expected serialization failure"),
     error => {
       do_check_false(firstCallback_happened);
       do_check_eq(error.message, expectedDataError);
       firstCallback_happened = true;
     });
 
+  // flush() will cancel the timer
   yield tester.flush(disabled_write_callback).then(
     count => do_throw("Expected serialization failure"),
     error => do_check_eq(error.message, expectedDataError)
     );
 
   do_check_true(firstCallback_happened);
 });
 
@@ -412,28 +504,30 @@ add_task(function data_throw_during_flus
 // finish writing (need to restart delayed timer)
 // saveChanges
 // flush
 // write starts
 // actually restart timer for delayed write
 // write completes
 // delayed timer goes off, throws error because DeferredSave has been torn down
 add_task(function delay_flush_race() {
-  let tester = DeferredSaveTester(5);
+  let timerPromise = setPromiseMockTimer();
+  let tester = DeferredSaveTester();
   let firstData = "First save";
   let secondData = "Second save";
   let thirdData = "Third save";
   let writeStarted = Promise.defer();
 
   function writeCallback(aTester) {
     writeStarted.resolve(aTester.waDeferred);
   }
 
   // This promise won't resolve until after writeStarted
   let firstSave = tester.save(firstData, writeCallback);
+  (yield timerPromise).callback();
 
   let writer = yield writeStarted.promise;
   // the first write has started
 
   // dirty the data and request another save
   let secondSave = tester.save(secondData);
 
   // complete the first write