1228827 - Firefox Sync forgets position of bookmarks separator

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P1)

Description

[Sergey Zolotarev]

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
Build ID: 20151030083518

Steps to reproduce:

1. Add a separator somewhere in the middle of the bookmarks menu 
2. Wait for sync
3. Run firefox on another system with the same Sync account


Actual results:

The bookmark separator was positioned at the bottom of the bookmarks menu instead of the original position.


Expected results:

Separator in the same position it was initially placed.

Comment 1

[Richard Newman [:rnewman]]

This certainly used to work. Sync synchronizes separator position with 'pos' to resolve conflicts with other separators, and child positioning for the rest.

Comment 2

[Sergey Zolotarev]

Can I somehow help to debug and/or fix this? I dual boot into Windows and Ubuntu daily and it's a little annoying. I could probably live without separators but I like to keep my bookmarks organized.

Comment 3

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

I happened to see this while I had logging enabled. I just connected an android emulator to my test account and after doing a Sync, our validator told me that on Desktop, "Record MCk-v4SG0eyk has differences between local and server copies: field="pos", localValue=4, serverValue=2

The logs that reference this item:

> 1464316241900	Sync.Engine.Bookmarks	TRACE	Incoming: { id: menu  index: 1000000  modified: 1464316139.51  ttl: undefined  payload: {"id":"menu","children":["PIrUsx6Q2o6b","htFM4hef_PFW","wCb4ZspvQ0g0","ZsXNl9WUqjIe","MCk-v4SG0eyk","buaNIJIeTStt","I6s-dTVEHJxm"],"parentid":"places","title":"Bookmarks Menu","type":"folder","parentName":""}  collection: bookmarks }

That's the new incoming "Bookmarks Menu" after the Fennec Sync. Note that the separator in question is at index 4 in the children array - I'm not sure that's relevant. Then later in the log:

> 1464316241964	Sync.Engine.Bookmarks	TRACE	Incoming: { id: MCk-v4SG0eyk  index: 0  modified: 1464316139.51  ttl: undefined  payload: {"id":"MCk-v4SG0eyk","parentid":"menu","type":"separator","pos":2,"parentName":"Bookmarks Menu"}  collection: bookmarks }

So this is the separator itself - it correctly references the parent, and the pos field is indeed 2 - even though it is at a different position in the children array above.

> 1464316241964	Sync.Store.Bookmarks	TRACE	Number of rows matching GUID MCk-v4SG0eyk: 0
> 1464316241964	Sync.Engine.Bookmarks	TRACE	Reconciling MCk-v4SG0eyk. exists=false; modified=false; local age=null; incoming age=97.30999994277954
> 1464316241964	Sync.Engine.Bookmarks	TRACE	Finding dupe for MCk-v4SG0eyk (already duped: undefined).
> 1464316241964	Sync.Engine.Bookmarks	TRACE	Finding mapping: Bookmarks Menu, s2
> 1464316241964	Sync.Engine.Bookmarks	TRACE	No dupe found for key s2/undefined.
> 1464316241964	Sync.Engine.Bookmarks	DEBUG	MCk-v4SG0eyk mapped to undefined
> 1464316241964	Sync.Engine.Bookmarks	TRACE	No duplicate found for incoming item: MCk-v4SG0eyk
> 1464316241964	Sync.Engine.Bookmarks	TRACE	Applying incoming because local item does not exist and was not deleted.
> 1464316241964	Sync.Store.Bookmarks	DEBUG	Applying record MCk-v4SG0eyk
> 1464316241964	Sync.Store.Bookmarks	DEBUG	Local parent is menu
> 1464316241964	Sync.Store.Bookmarks	DEBUG	Record is not an orphan.
> 1464316241964	Sync.Store.Bookmarks	TRACE	Number of rows matching GUID MCk-v4SG0eyk: 0

The above is (correctly) reflecting that it's not a dupe of an existing item.

> 1464316241965	Sync.Store.Bookmarks	DEBUG	created separator 35 under 2

Here we've just created the new separator at https://dxr.mozilla.org/mozilla-central/rev/8d0aadfe7da782d415363880008b4ca027686137/services/sync/modules/engines/bookmarks.js#761 - but that code specifies PlacesUtils.bookmarks.DEFAULT_INDEX as the position for the separator - so it was appended to the end.

The server and local copies of the menu match - both have that separator at an index of 4 - but the record for the separator on the server still has a position of 2. As only separators seem to record their position on the server (ie, normal bookmark and folder records do not - I don't understand this) I can't tell if the other items in the menu have been "pushed down".

Richard, do you happen to remember why we use DEFAULT_INDEX, or know a good reason we shouldn't use "pos" here? That would seem to explain the symptoms in comment 0. It seems to have been introduced in bug 615285 (which ironically is titled "Bookmark sync: track ordering on folder" :) Sadly there's nothing in the bug comments that makes it obvious.

Comment 4

[Richard Newman [:rnewman]]

AIUI 'pos' isn't actually used; it's only used to disambiguate between multiple separators in the same folder and avoid them being duped together.

Fennec doesn't understand separators (BookmarkRecord.java line 245), so if it ever has to reupload them it'll spit them back out with that pos field unchanged. That's why the record on the server still has '2'.


> Richard, do you happen to remember why we use DEFAULT_INDEX, or know a good
> reason we shouldn't use "pos" here? That would seem to explain the symptoms
> in comment 0. It seems to have been introduced in bug 615285 (which
> ironically is titled "Bookmark sync: track ordering on folder" :) Sadly
> there's nothing in the bug comments that makes it obvious.

There's a lot of legacy crap in the bookmark format; it even used to have sibling pointers. These days we _only_ use the `children` array for positioning; e.g., iOS only uses parent pointers for error-checking.

When desktop creates or moves a separator, I see no reason why it shouldn't use the parent's `children` array to decide where to put it. We should avoid using 'pos'; we can keep it around to continue to avoid smushing, but not for positioning.

Comment 5

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

That makes sense, thanks. Note that the "pos" appears to be always wrong on desktop too - what I believe happens is:

* new separator gets created as the last child - new record created for that separator with pos reflecting it being at the end of the list.
* user then moves the separator - the parent record gets marked as changed, but *not* the sep itself (as it's a change in the same folder)
* new folder record is written with the separator in the correct child position - but the original separator record still has the old "pos".

It's not yet clear to me exactly what this means to the de-duping..

So I think comment 0 is reflecting the "tracker missed changes" bug and probably goes something like:

* User creates new separator, and it's always added to the end.
* This triggers a sync.
* Before Sync completes the user has moved the separator to the preferred position.
* Sync finished and it's missed the notification for the move, so server record of the folder still reflects it being at the end.

Comment 6

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

so yeah, sadly nothing actionable here other than the tracker fixes...

Comment 7

[Chris Karlof [:ckarlof]]

Removing priority on this, since it should be addressed by bug 1258127.

Comment 8

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

We recently did some work around this - I'll find the other bugs.

Comment 9

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

(In reply to Mark Hammond [:markh] from comment #8)
> We recently did some work around this - I'll find the other bugs.

This is the bug I was looking for :/ Let's see where bug 1258127 leaves us.

Comment 10

[Richard Newman [:rnewman]]

Marking this as NEW because it's certainly a known issue -- separators rely on their pos to match in guidMap, so they'll breed on merge with different GUIDs, and they'll be repositioned if their server pos doesn't match.

Comment 11

[Lina Butler [:lina]]

Nominating this for promotion to P2 during our next triage, per Richard's suggestion in bug 1258127, comment 266.

> Follow-up: mark as changed all Separator siblings with an index greater than either the source or destination indices. They'll need new 'pos' values. (Fixes Bug 1228827.)

Comment 12

[Adrian Florinescu [:aflorinescu]]

Mark, is this bug still needing a test-case?

Comment 13

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

(In reply to Adrian Florinescu [:AdrianSV] [No PTO left this year - NI me if required] from comment #12)
> Mark, is this bug still needing a test-case?

Thanks for asking - I think we've identified what we intend doing here, so no additional test case is necessary.

Comment 14

[Edouard Oger [:eoger]]

Attachment: Bug 1228827 - Sync correctly the bookmark separators positions.

Review commit: https://reviewboard.mozilla.org/r/107604/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/107604/

Comment 15

[Edouard Oger [:eoger]]

Here's a wip, however it seems the problem only arises when we use the "insert separator" command and my patch doesn't help for this use case. I didn't have any problems when moving the separator directly or when moving the regular bookmarks around it.
I'm very unfamiliar with that part of the code base, am I going in the right direction here?

Comment 16

[Lina Butler [:lina]]

Comment on attachment 8830935 [details]
Bug 1228827 - Sync correctly the bookmark separators positions.

https://reviewboard.mozilla.org/r/107604/#review109068

You're definitely on the right track! We'll want to call `AdjustSeparatorsSyncCounter` in `CreateFolder`, `InsertBookmark`, and `RemoveItem`, too, and Bookmarks.jsm will need a similar treatment.

::: toolkit/components/places/nsNavBookmarks.cpp:345
(Diff revision 1)
>  
>  
> +nsresult
> +nsNavBookmarks::AdjustSeparatorsSyncCounter(int64_t aFolderId,
> +                                            int32_t aStartIndex,
> +                                            int64_t aSyncChangeDelta)

Nit: Bail if `!aSyncChangeDelta`.

::: toolkit/components/places/nsNavBookmarks.cpp:1453
(Diff revision 1)
>    if (sameParent) {
>      // If we're moving within the same container, only the parent needs a sync
>      // change. Update the item's last modified date without bumping its counter.
>      rv = SetItemDateInternal(LAST_MODIFIED, 0, bookmark.id, now);
>      NS_ENSURE_SUCCESS(rv, rv);
> +    // Mark all affected separators as changed

I think we'll want to call this unconditionally. If we're moving an item into a different folder, the positions of its former siblings will still change.

Comment 17

[Edouard Oger [:eoger]]

Comment on attachment 8830935 [details]
Bug 1228827 - Sync correctly the bookmark separators positions.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/107604/diff/1-2/

Comment 18

[Edouard Oger [:eoger]]

Comment on attachment 8830935 [details]
Bug 1228827 - Sync correctly the bookmark separators positions.

Thank you Kit, I addressed your comments and it fixes the problem on my machine.

Comment 19

[Lina Butler [:lina]]

Comment on attachment 8830935 [details]
Bug 1228827 - Sync correctly the bookmark separators positions.

https://reviewboard.mozilla.org/r/107604/#review109676

Great!

Could you please add some tests to test_sync_utils, and maybe test_sync_fields? I think we already have some for the sync and async methods; let's just make sure `pullChanges` returns the right GUIDs. In particular, let's test modifying an item in a folder containing separators, and modifying a separator itself.

::: toolkit/components/places/Bookmarks.jsm:877
(Diff revision 2)
>                   lowIndex: Math.min(item.index, newIndex),
>                   highIndex: Math.max(item.index, newIndex) });
> +
> +          // Mark all affected separators as changed
> +          const startIndex = Math.min(newIndex, item.index);
> +          yield adjustSeparatorsSyncCounter(db, newParent._id, startIndex, syncChangeDelta);

Nice. Doing this after the `UPDATE` also has the desirable effect of bumping the item's change counter if it's a separator. Could you please mention that in the comment, or add a test that moves a separator? I'd like to make sure we don't accidentally break this in the future.

::: toolkit/components/places/Bookmarks.jsm:1027
(Diff revision 2)
>               title: item.title, date_added: PlacesUtils.toPRTime(item.dateAdded),
>               last_modified: PlacesUtils.toPRTime(item.lastModified), guid: item.guid,
>               syncChangeCounter: syncChangeDelta, syncStatus });
>  
> +      // Mark all affected separators as changed
> +      yield adjustSeparatorsSyncCounter(db, parent._id, item.index, syncChangeDelta);

Nit: Maybe `index + 1` here, sice inserting an item will already bump its change counter? It doesn't really matter, though; we expect some changes to bump the counter multiple times as it is. But it might make tests easier to skim.

::: toolkit/components/places/Bookmarks.jsm:1790
(Diff revision 2)
> +function adjustSeparatorsSyncCounter(db, parentId, startIndex, syncChangeDelta) {
> +  if (!syncChangeDelta) {
> +    return Promise.resolve();
> +  }
> +
> +  return db.execute(`

Nit: `db.executeCached`, since we expect to run this multiple times.

::: toolkit/components/places/nsNavBookmarks.cpp:343
(Diff revision 2)
>    return NS_OK;
>  }
>  
>  
> +nsresult
> +nsNavBookmarks::AdjustSeparatorsSyncCounter(int64_t aFolderId,

Sorry, I forgot to mention `SetItemIndex`. It's deprecated, but I see we still call it in `PlacesTransactions.SortByName`, so let's have it call your new method, too.

::: toolkit/components/places/nsNavBookmarks.cpp:347
(Diff revision 2)
> +nsresult
> +nsNavBookmarks::AdjustSeparatorsSyncCounter(int64_t aFolderId,
> +                                            int32_t aStartIndex,
> +                                            int64_t aSyncChangeDelta)
> +{
> +  NS_ASSERTION(aStartIndex >= 0, "Bad start position");

Nit: Let's use `MOZ_ASSERT` for new code. It's fatal; I think `NS_ASSERTION` isn't.

::: toolkit/components/places/nsNavBookmarks.cpp:552
(Diff revision 2)
>      rv = AddSyncChangesForBookmarksWithURI(aURI, syncChangeDelta);
>      NS_ENSURE_SUCCESS(rv, rv);
>    }
>  
> +  // Mark all affected separators as changed
> +  rv = AdjustSeparatorsSyncCounter(aParentId, aIndex, syncChangeDelta);

Ditto my nits about `aIndex + 1` in the JS code.

Comment 20

[Edouard Oger [:eoger]]

Comment on attachment 8830935 [details]
Bug 1228827 - Sync correctly the bookmark separators positions.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/107604/diff/2-3/

Comment 21

[Edouard Oger [:eoger]]

Thank you kit, I addressed your comments and added tests :)

Comment 22

[Lina Butler [:lina]]

Comment on attachment 8830935 [details]
Bug 1228827 - Sync correctly the bookmark separators positions.

https://reviewboard.mozilla.org/r/107604/#review109990

Thanks, LGTM!

Comment 23

[Lina Butler [:lina]]

Comment on attachment 8830935 [details]
Bug 1228827 - Sync correctly the bookmark separators positions.

https://reviewboard.mozilla.org/r/107604/#review109992

::: toolkit/components/places/tests/unit/test_sync_utils.js:2178
(Diff revision 3)
> +
> +  yield setChangesSynced(changes);
> +
> +  do_print("Move a separator around directly");
> +  let separatorId = yield syncIdToId(separator.syncId);
> +  PlacesUtils.bookmarks.moveItem(separatorId, parentId, 0);

Maybe move the separator with `PlacesUtils.bookmarks.update` here, just to make sure the async version works the same way.

Comment 24

[Edouard Oger [:eoger]]

Comment on attachment 8830935 [details]
Bug 1228827 - Sync correctly the bookmark separators positions.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/107604/diff/3-4/

Comment 25

[Thom Chiovoloni [:tcsc] (ex-moco)]

We should consider undoing the work done in bug 1276152 if this property will be correct now.

Comment 26

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b08678881859
Sync correctly the bookmark separators positions. r=kitcambridge

Comment 27

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/b08678881859

Comment 28

[Saheda Reza [:Antora]]

i have reproduced this bug on firefox nightly according to(2015-11-29)

Fixing bug is verified on Latest Developer Edition-- Build ID : (20170402004002),User Agent: Mozilla/5.0 (Windows NT 10.0; rv:54.0) Gecko/20100101 Firefox/54.0

Tested OS -- Windows10 32bit
 [bugday-20170329]