Bug 550627 - Default reconciliation to server wins for older changed items [r=mconnor]

Save the time the tracker adds a new changed id and use that to compare the age of the record on the server vs the age of the local change to decide if it's server wins or client wins. Fix up various direct uses of changedIDs to use the API and make the save-to-disk lazy to avoid excessive writes. Add a test to make sure addChangedID only increases in time.

services/sync/modules/engines.js

@@ -434,14 +434,11 @@ SyncEngine.prototype = {
       CryptoMetas.set(meta.uri, meta);
     }
 
-    // first sync special case: upload all items
-    // NOTE: we use a backdoor (of sorts) to the tracker so it
-    // won't save to disk this list over and over
+    // Mark all items to be uploaded, but treat them as changed from long ago
     if (!this.lastSync) {
       this._log.debug("First sync, uploading all items");
-      this._tracker.clearChangedIDs();
-      [i for (i in this._store.getAllIDs())]
-        .forEach(function(id) this._tracker.changedIDs[id] = true, this);
+      for (let id in this._store.getAllIDs())
+        this._tracker.addChangedID(id, 0);
     }
 
     let outnum = [i for (i in this._tracker.changedIDs)].length;
@@ -592,7 +589,7 @@ SyncEngine.prototype = {
       this._log.trace("Preferring local id: " + [dupeId, item.id]);
       this._deleteId(item.id);
       item.id = dupeId;
-      this._tracker.changedIDs[dupeId] = true;
+      this._tracker.addChangedID(dupeId, 0);
     }
     else {
       this._log.trace("Switching local id to incoming: " + [item.id, dupeId]);
@@ -601,44 +598,36 @@ SyncEngine.prototype = {
     }
   },
 
-  // Reconciliation has three steps:
-  // 1) Check for the same item (same ID) on both the incoming and outgoing
-  //    queues.  This means the same item was modified on this profile and
-  //    another at the same time.  In this case, this client wins (which really
-  //    means, the last profile you sync wins).
-  // 2) Check if the incoming item's ID exists locally.  In that case it's an
-  //    update and we should not try a similarity check (step 3)
-  // 3) Check if any incoming & outgoing items are actually the same, even
-  //    though they have different IDs.  This happens when the same item is
-  //    added on two different machines at the same time.  It's also the common
-  //    case when syncing for the first time two machines that already have the
-  //    same bookmarks.  In this case we change the IDs to match.
   _reconcile: function SyncEngine__reconcile(item) {
     if (this._log.level <= Log4Moz.Level.Trace)
       this._log.trace("Incoming: " + item);
 
-    // Step 1: Check for conflicts
-    //         If same as local record, do not upload
-    this._log.trace("Reconcile step 1");
+    this._log.trace("Reconcile step 1: Check for conflicts");
     if (item.id in this._tracker.changedIDs) {
-      if (this._isEqual(item))
+      // If the incoming and local changes are the same, skip
+      if (this._isEqual(item)) {
         this._tracker.removeChangedID(item.id);
-      return false;
+        return false;
+      }
+
+      // Records differ so figure out which to take
+      let recordAge = Resource.serverTime - item.modified;
+      let localAge = Date.now() / 1000 - this._tracker.changedIDs[item.id];
+      this._log.trace("Record age vs local age: " + [recordAge, localAge]);
+
+      // Apply the record if the record is newer (server wins)
+      return recordAge < localAge;
     }
 
-    // Step 2: Check for updates
-    //         If different from local record, apply server update
-    this._log.trace("Reconcile step 2");
+    this._log.trace("Reconcile step 2: Check for updates");
     if (this._store.itemExists(item.id))
       return !this._isEqual(item);
 
-    // If the incoming item has been deleted, skip step 3
-    this._log.trace("Reconcile step 2.5");
+    this._log.trace("Reconcile step 2.5: Don't dupe deletes");
     if (item.deleted)
       return true;
 
-    // Step 3: Check for similar items
-    this._log.trace("Reconcile step 3");
+    this._log.trace("Reconcile step 3: Find dupes");
     let dupeId = this._findDupe(item);
     if (dupeId)
       this._handleDupe(item, dupeId);

services/sync/modules/engines/bookmarks.js

@@ -206,7 +206,7 @@ BookmarksEngine.prototype = {
     // Trigger id change from dupe to winning and update the server
     this._store.changeItemID(dupeId, item.id);
     this._deleteId(dupeId);
-    this._tracker.changedIDs[item.id] = true;
+    this._tracker.addChangedID(item.id, 0);
   }
 };
 

services/sync/modules/engines/tabs.js

@@ -75,11 +75,6 @@ TabEngine.prototype = {
     this._store.wipe();
   },
 
-  _syncFinish: function _syncFinish() {
-    SyncEngine.prototype._syncFinish.call(this);
-    this._tracker.resetChanged();
-  },
-
   /* The intent is not to show tabs in the menu if they're already
    * open locally.  There are a couple ways to interpret this: for
    * instance, we could do it by removing a tab from the list when
@@ -209,8 +204,6 @@ TabStore.prototype = {
 function TabTracker(name) {
   Tracker.call(this, name);
 
-  this.resetChanged();
-
   // Make sure "this" pointer is always set correctly for event listeners
   this.onTab = Utils.bind2(this, this.onTab);
 
@@ -257,15 +250,10 @@ TabTracker.prototype = {
   onTab: function onTab(event) {
     this._log.trace(event.type);
     this.score += 1;
-    this._changedIDs[Clients.localID] = true;
+    this.addChangedID(Clients.localID);
 
     // Store a timestamp in the tab to track when it was last used
     Svc.Session.setTabValue(event.originalTarget, "weaveLastUsed",
                             Math.floor(Date.now() / 1000));
   },
-
-  get changedIDs() this._changedIDs,
-
-  // Provide a way to empty out the changed ids
-  resetChanged: function resetChanged() this._changedIDs = {}
 }

services/sync/modules/resource.js

@@ -308,6 +308,13 @@ ChannelListener.prototype = {
 
   onStartRequest: function Channel_onStartRequest(channel) {
     channel.QueryInterface(Ci.nsIHttpChannel);
+
+    // Save the latest server timestamp when possible
+    try {
+      Resource.serverTime = channel.getResponseHeader("X-Weave-Timestamp") - 0;
+    }
+    catch(ex) {}
+
     this._log.trace(channel.requestMethod + " " + channel.URI.spec);
     this._data = '';
 

services/sync/modules/service.js

@@ -885,7 +885,7 @@ WeaveSvc.prototype = {
       return false;
     }
     else if (meta.payload.syncID != this.syncID) {
-      this.resetService();
+      this.resetClient();
       this.syncID = meta.payload.syncID;
       this._log.debug("Clear cached values and take syncId: " + this.syncID);
 

services/sync/modules/trackers.js

@@ -68,6 +68,7 @@ function Tracker(name) {
   this._score = 0;
   this._ignored = [];
   this.ignoreAll = false;
+  this.changedIDs = {};
   this.loadChangedIDs();
 }
 Tracker.prototype = {
@@ -95,29 +96,15 @@ Tracker.prototype = {
     this._score = 0;
   },
 
-  /*
-   * Changed IDs are in an object (hash) to make it easy to check if
-   * one is already set or not.
-   * Note that it would be nice to make these methods asynchronous so
-   * as to not block when writing to disk.  However, these will often
-   * get called from observer callbacks, and so it is better to make
-   * them synchronous.
-   */
-
-  get changedIDs() {
-    let items = {};
-    this.__defineGetter__("changedIDs", function() items);
-    return items;
-  },
-
   saveChangedIDs: function T_saveChangedIDs() {
-    Utils.jsonSave("changes/" + this.file, this, this.changedIDs);
+    Utils.delay(function() {
+      Utils.jsonSave("changes/" + this.file, this, this.changedIDs);
+    }, 1000, this, "_lazySave");
   },
 
   loadChangedIDs: function T_loadChangedIDs() {
     Utils.jsonLoad("changes/" + this.file, this, function(json) {
-      for (let id in json)
-        this.changedIDs[id] = 1;
+      this.changedIDs = json;
     });
   },
 
@@ -136,16 +123,22 @@ Tracker.prototype = {
       this._ignored.splice(index, 1);
   },
 
-  addChangedID: function T_addChangedID(id) {
+  addChangedID: function addChangedID(id, when) {
     if (!id) {
       this._log.warn("Attempted to add undefined ID to tracker");
       return false;
     }
     if (this.ignoreAll || (id in this._ignored))
       return false;
-    if (!this.changedIDs[id]) {
-      this._log.trace("Adding changed ID " + id);
-      this.changedIDs[id] = true;
+
+    // Default to the current time in seconds if no time is provided
+    if (when == null)
+      when = Math.floor(Date.now() / 1000);
+
+    // Add/update the entry if we have a newer time
+    if ((this.changedIDs[id] || -Infinity) < when) {
+      this._log.trace("Adding changed ID: " + [id, when]);
+      this.changedIDs[id] = when;
       this.saveChangedIDs();
     }
     return true;
@@ -158,7 +151,7 @@ Tracker.prototype = {
     }
     if (this.ignoreAll || (id in this._ignored))
       return false;
-    if (this.changedIDs[id]) {
+    if (this.changedIDs[id] != null) {
       this._log.trace("Removing changed ID " + id);
       delete this.changedIDs[id];
       this.saveChangedIDs();
@@ -168,9 +161,7 @@ Tracker.prototype = {
 
   clearChangedIDs: function T_clearChangedIDs() {
     this._log.trace("Clearing changed ID list");
-    for (let id in this.changedIDs) {
-      delete this.changedIDs[id];
-    }
+    this.changedIDs = {};
     this.saveChangedIDs();
   }
 };

services/sync/tests/unit/test_tracker_addChanged.js

@@ -0,0 +1,25 @@
+Cu.import("resource://weave/trackers.js");
+
+function run_test() {
+  let tracker = new Tracker();
+  let id = "the_id!";
+
+  _("Make sure nothing exists yet..");
+  do_check_eq(tracker.changedIDs[id], null);
+
+  _("Make sure adding of time 0 works");
+  tracker.addChangedID(id, 0);
+  do_check_eq(tracker.changedIDs[id], 0);
+
+  _("A newer time will replace the old 0");
+  tracker.addChangedID(id, 10);
+  do_check_eq(tracker.changedIDs[id], 10);
+
+  _("An older time will not replace the newer 10");
+  tracker.addChangedID(id, 5);
+  do_check_eq(tracker.changedIDs[id], 10);
+
+  _("Adding without time defaults to current time");
+  tracker.addChangedID(id);
+  do_check_true(tracker.changedIDs[id] > 10);
+}