1235269 - Changes made during a Sync may be ignored causing items to be missing or deleted items to be resurrected

Status: RESOLVED DUPLICATE of bug 1258127

(Firefox :: Sync, defect, P1)

Description

[Richard Newman [:rnewman]]

In August I created two bookmarks, numbers 49 and 50 in my 'Recipes' folder.

These bookmarks were created on desktop, seven seconds apart, clearing open tabs:

  Mon Aug 10 12:52:02 PDT 2015
  Mon Aug 10 12:52:09 PDT 2015

Firefox for iOS's consistency checker just told me those weren't present in my iOS server bookmarks buffer.

And sure enough, they're not on the server.

Desktop places.sqlite:

---
$ sqlite3 places.sqlite "select * from moz_bookmarks where guid in ('FtN9dOhARjHD', 'r1jDGaKZ_003');"
id          type        fk          parent      position    title                                          keyword_id  folder_type  dateAdded         lastModified      guid
----------  ----------  ----------  ----------  ----------  ---------------------------------------------  ----------  -----------  ----------------  ----------------  ------------
6545        1           365326      4760        49          Red Braised Pork Belly – China Sichuan Food                           1439236322479000  1439236325532000  FtN9dOhARjHD
6546        1           365324      4760        50          Hong Shao Rou Recipe—(Red Braised Pork Bell                           1439236329874000  1439236332351000  r1jDGaKZ_003
---

There's no mention of these two in $profiledir/weave/ -- not in failed, not in logs, nothing.

They're not on the server if I try to fetch them:

	Sync.RecordManager	TRACE	Importing record: https://sync-221-us-west-2.sync.services.mozilla.com/1.5/23528203/storage/bookmarks/FtN9dOhARjHD?full=1
	Sync.Resource	DEBUG	mesg: GET fail 404 https://sync-221-us-west-2.sync.services.mozilla.com/1.5/23528203/storage/bookmarks/FtN9dOhARjHD?full=1
	Sync.Resource	DEBUG	GET fail 404 https://sync-221-us-west-2.sync.services.mozilla.com/1.5/23528203/storage/bookmarks/FtN9dOhARjHD?full=1

but their parent record on the server claims to have them as children!

{"id":"zU14bWY9AY2q","type":"folder","parentName":"Food","title":"Recipes","description":null,"children":["gPtraaq3VWS5","7LnanjWSE2dR","-qt32FFduyTJ","Vcu0b7Yhyr4n","1UIsVacGOpN_","M8-C6xNEPi01","lEEm3OoVkJck","beGBJU_GID35","1UOFRd58a7EM","-mhx_iQ8mvSu","cUpFZYps3PgB","3loYBiI1WMQA","o-Oyai_TDzkI","gGRhexfu1H6Y","sLOW0Rd12Kfz","RLn7qrosrL29","nKcHznZnX6-x","Dt4Jcn2F1cJn","WebaD9RvROZJ","KSzu2knU5LMT","LQnsH-pBfuAW","eeaW4iEjXaBJ","O934Gm6wjHIz","92m9yf5C_Aet","TIBhr9etGCZm","d5d0GJyKc7gA","I2Ls3ozDhLt4","37pp7btj9nuz","iNkz8Op0q-g9","bp4y7IEMguuy","YcZz37xZzZvy","3vxmJS25Aq0Q","UjF0VSTfajsk","9QPx1xnJGBQi","NZlA1kRy4RKk","BDT-_LLi4Ssy","lqutaAqQcOfx","RQgvat9frau-","OD8_0Hl74Bgr","unsk_8WEhPiw","E94LZbmeVlBh","HJminkGHuc1M","f7NG7DDqqOjX","aFMOyHIfvVIn","IgUlW4QKuYK6","_PbdCkXyuEZa","KFHHY3ht0rba","ZrSoa9iPr81O","97MIzlWVx6cO","FtN9dOhARjHD","r1jDGaKZ_003","4g43-Q8BE4VV","kWQOZGTngK8Y"],"parentid":"5lQz_glXhEtn"}



These logs imply one of two things:

* The server accepted a POST containing the changed parent folder, but dropped the two new records on the floor.
* The client never uploaded the two new records, either because they were skipped, because we thought they were uploaded successfully, or because they were never entered into the tracker.

I'll bet on the latter. Another record, 97MIzlWVx6cO, was created 4 seconds earlier:

  Mon Aug 10 12:51:58 PDT 2015

so my hypothesis is this:

* The user saves a bookmark.
* We begin a sync. This sets ignoreAll so we don't trigger ourselves.
* The user bookmarks another link. We ignore it. They bookmark another, and we ignore that, too.
* All three bookmarks are in the same folder. We eventually come to upload that, and -- because we go to the DB to compute the record -- all three bookmarks appear in the uploaded parent record!

This bug worries me, because my sample size has reached *1* and I've already found bookmark corruption that would cause iOS to back off for fear of doing more damage.


All you need to do to hit this bug is bookmark two pages faster than Sync can complete -- four seconds seems to be enough.

One more check mark next to "blind trust in observer notifications is bad". This explains another slice of bookmark quality issues over the past few years.


Fixes or mitigations for this bug might be:

* Narrow the ignoreAll window.

* Don't use observer notifications for change tracking. See <http://160.twinql.com/syncing-and-storage-on-three-platforms/>.

* If we're uploading a folder, make sure -- through any means; fetching IDs from the server, checking timestamps against when our sync began, annotating bookmarks that we've uploaded them ever -- that we've uploaded all of its children. Eventual consistency is better than none.

* …

Comment 1

[Richard Newman [:rnewman]]

Note that fixes that are scoped to an individual folder within a sync aren't sufficient. The same problem exists at longer timescales:

* Hit the bookmark star to add an Unsorted Bookmark. A sync begins.
* Drag a URL to the toolbar. A bookmark is created, but neither the new bookmark nor the changed toolbar is marked as changed.
* Wait for the sync to finish.
* Weeks later, drag another bookmark to the toolbar. The uploaded toolbar record now includes two children, only one of which is new and only one of which will be uploaded to the server.


When another client downloads these incomplete sets, it'll do one of three things:


* Quietly screw up until it makes a local change, then screw up other clients. (Desktop)

* Actively fix up the damage, then push the changes. (Android)
 -- This will screw up the original desktop, which will move its local-never-synced bookmarks to Unsorted Bookmarks as it realizes the magnitude of its error.

* Refuse to sync (either the whole tree or the smallest inconsistent subtree) until the server gets its shit in order. (iOS)
 -- I might end up having the iOS client send reset commands to try to force other clients to fix things, but that doesn't make me happy.

We've been seeing these symptoms as a quiet hum of complaints for years, so it's nice to have another explanation beyond Bug 814801.

Comment 2

[Richard Newman [:rnewman]]

Here's some chrome JS that'll see if your account is missing records.

//////////
function removeAll(xs, ys) {
  ys.forEach((y) => xs.delete(y));
  return xs;
}

let bme = Weave.Service.engineManager.get("bookmarks");
let bms = bme._store;
let local = Object.keys(bms.getAllIDs());
let remote = JSON.parse(Weave.Service.resource(Weave.Service.storageURL + "bookmarks").get());

let missing = removeAll(new Set(local), remote);

console.log(missing);

// Set [ "FtN9dOhARjHD", "r1jDGaKZ_003" ]
//////////


A reasonable fix might be to run this and add the results to the tracker:

//////////
missing.forEach((id) => bme._tracker.addChangedID(id, Date.now()));
//////////

Comment 3

[Mark Hammond [:markh] [:mhammond]]

(In reply to Richard Newman [:rnewman] from comment #2)
> Here's some chrome JS that'll see if your account is missing records.

This reports 58 records for my real profile :(

Comment 4

[Nick Alexander :nalexander [he/him]]

(In reply to Mark Hammond [:markh] from comment #3)
> (In reply to Richard Newman [:rnewman] from comment #2)
> > Here's some chrome JS that'll see if your account is missing records.
> 
> This reports 58 records for my real profile :(

I have 605 bookmarks and none reported missing.  Victory!

Comment 5

[Mark Hammond [:markh] [:mhammond]]

FTR, the same issue obviously exists with deletions, resulting in the server still having records that don't exist locally (because we were syncing when they were deleted). When the next client for that account does a full sync (eg, a new device) those "deleted" bookmarks spring back into life. My test profiles have thousands of such records.

Comment 6

[Mark Hammond [:markh] [:mhammond]]

I'm going to steal this as a meta bug for the general problem discussed above.

Comment 7

[Richard Newman [:rnewman]]

I've also seen the opposite, just now: a record that's present on the server, not deleted, yet not present in its parent's child list. The consistency checker catches this, too.

Comment 8

[Mark Hammond [:markh] [:mhammond]]

To be clear, isn't this the same issue as comment 5? ie, a bookmark manually deleted during a sync causes it to be removed locally but left on the server, and thus resurrected next time a client does a full sync?

Comment 9

[Richard Newman [:rnewman]]

(In reply to Mark Hammond [:markh] from comment #8)
> To be clear, isn't this the same issue as comment 5? ie, a bookmark manually
> deleted during a sync causes it to be removed locally but left on the
> server, and thus resurrected next time a client does a full sync?

I think in your scenario the server is still consistent: the deletion is missed, and neither the deleted record nor the changed parent is uploaded, right?

In this situation a record is present on the server but its parent on the server doesn't mention it. That means we either:

* Uploaded the new record, but didn't upload its changed parent.
* Raced with another client uploading that parent, losing that write.
* Deleted the record locally, uploaded the parent but not the deleted record, and then redownloaded the record and didn't update the server parent.

In theory, the last scenario should mark the parent as changed when we find a parent folder for the new record, so the server parent should end up consistent. Dunno if it works that way in practice, but that's the theory :)

Comment 10

[Richard Newman [:rnewman]]

Mark: would it be worth splitting this bug into "don't fail to track changes" and "recover from having missed changes"?

The latter might be a once-per-week hook before/after a sync or something like that -- fairly tractable -- and I'd love for clients to be able to recover from this automatically.

The hook might be as simple as fetching info/collection_counts, fetching and processing the ID list as in Comment 2 if the counts don't match.

Comment 11

[Richard Newman [:rnewman]]

We now have preliminary telemetry data from iOS users. This is a very small sample size: about 63 users.

Above 0 bookmarks, your chance of your server data being correct is 68%.
Above 222 bookmarks, your chance is 50-50.
Above 1000 bookmarks, your chance is just 37%.



20 users have bookmark data that isn't correct. Only one user recovered on a subsequent attempt.

Of these 20 users, there were:

9 users with parentid disagreements -- where a record's parentid did not match up to the children array in a folder.
12 users with missing records -- where a record is mentioned as a child of a folder but not present on the server.
16 users with missing structure -- where a folder isn't present but a record claims that's where it lives.
8 users with overlapping structure -- where more than one folder claims to own a child.


Probably many of these are caused by the same root issue: failing to track a change, and an ongoing sync seeing partial state.


In short: our frequent bookmark users have a very high chance of failure, and we need to do significant work to make sure that desktop clients behave more correctly.

Comment 12

[Richard Newman [:rnewman]]

Attachment: Failures by count of records

Comment 13

[Chris Karlof [:ckarlof]]

How would I have gotten into a state of my remote having 342 records and my local having 207 records?

Comment 14

[Chris Karlof [:ckarlof]]

Orphaned records could be one. Richard do you have a JS script which does the analysis in comment 11?

Comment 15

[Nick Alexander :nalexander [he/him]]

(In reply to Chris Karlof [:ckarlof] from comment #13)
> How would I have gotten into a state of my remote having 342 records and my
> local having 207 records?

Deleted records?

Comment 16

[Chris Karlof [:ckarlof]]

> Deleted records?

Yeah. I should write a script to figure this out. :)

Comment 17

[Richard Newman [:rnewman]]

(In reply to Nick Alexander :nalexander from comment #15)
> (In reply to Chris Karlof [:ckarlof] from comment #13)
> > How would I have gotten into a state of my remote having 342 records and my
> > local having 207 records?
> 
> Deleted records?

Most likely exactly that: every bookmark you delete locally remains as a deleted record on the server, forever and ever, until you get assigned to a new server or change your password.

Something like this should print "135" for you:

---
Components.utils.import("resource://services-sync/main.js");
Components.utils.import("resource://services-sync/record.js");

let collection = "bookmarks";

let bme = Weave.Service.engineManager.get(collection);
let recordType = bme._recordObj;
let coll = new Collection(Weave.Service.storageURL + collection, recordType, Weave.Service);

var deleted = [];
let collKey = Weave.Service.collectionKeys.keyForCollection(collection);

coll.full = true;
coll.limit = 500;
coll.recordHandler = function(item) {
  item.collection = collection;
  item.decrypt(collKey);
  if (item.cleartext.deleted) {
    deleted.push(item.id);
  }
};
coll.get();

console.log("Deleted: " + deleted.length);

---

Comment 18

[Richard Newman [:rnewman]]

(In reply to Chris Karlof [:ckarlof] from comment #14)
> Richard do you have a JS script which does
> the analysis in comment 11?

Sadly not; this relies on the structure extracted by the iOS bookmark mirrorer. The validation is expressed in SQL here:

https://github.com/mozilla/firefox-ios/blob/master/Storage/SQL/SQLiteBookmarksSyncing.swift#L677

It would be easy enough to write a bit of desktop JS to download everything and do similar analysis in memory.

Comment 19

[Edwin Wong [:edwong]]

this is essentially a dupe of bug 1258127 , just setting it as blocks for now.

Comment 20

[Richard Newman [:rnewman]]

Probably should check the other engines for similar problems, too.

Comment 21

[Mark Hammond [:markh] [:mhammond]]

(In reply to Richard Newman [:rnewman] from comment #20)
> Probably should check the other engines for similar problems, too.

Yep, we will probably only get to bookmarks this quarter.