Duplicate 'Recent Tags' menu in Bookmarks Library

VERIFIED FIXED in Firefox 61

Status

()

defect
P1
normal
VERIFIED FIXED
Last year
Last year

People

(Reporter: kkumari, Assigned: lina)

Tracking

(Blocks 1 bug)

unspecified
Firefox 61
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox61 fixed)

Details

Attachments

(5 attachments, 2 obsolete attachments)

Reporter

Description

Last year
Posted image Tags.PNG
Prerequisite:
1. About:sync addon installed
2. services.sync.engine.bookmarks.buffer is set to true

STR:
1. Tag some bookmarks
2. Sync two or more devices

Observed: Duplicate 'Recent Tags' menu in Bookmarks Library. Most Visited menu is missing.
Derp. Could you please share a de-anonymized export from About Sync? Thanks!
Flags: needinfo?(kkumari)
Reporter

Comment 2

Last year
Posted file sync
Please see attached de-anonymized export from About Sync.
Flags: needinfo?(kkumari)
Thanks, Kanchan, that's very helpful! The validation output for that tree does not look good at all. :-( Children appearing in multiple folders, parent-child disagreements, and a deleted item appearing as a child of a folder. Could you please upload the entire `weave` folder from that profile? I'd especially like to see the logs and `bookmarks.sqlite`. Also, which other operations did you test, and what devices are connected to the account?
Flags: needinfo?(kkumari)
Reporter

Comment 4

Last year
Posted file Weave Folder (obsolete) —
Please find 'weave' folder attached.

This FxA is connected to Windows, Linux, Mac, iOS and android devices.

Nightly on SVUS0014 (Windows)
Nightly on kanchans-MacBook-Pro
Nightly on Nexus 5 (Android)
Nightly on svuser-VirtualBox (Linux)
Firefox Beta on Softvision’s iPhone

This bug I encountered by simply just syncing to different devices and taggin some bookmarks.
I did some multiple operation today with identical set of bookmarks and got bug 1437153
Flags: needinfo?(kkumari)
Reporter

Comment 5

Last year
Posted file weave.zip
Reporter

Updated

Last year
Attachment #8949872 - Attachment is obsolete: true
Flags: needinfo?(markh)
Posted patch t.patch (obsolete) — Splinter Review
I started playing with this a little and thought I'd share what I have now to see if Kit has any thoughts.

(In reply to Kit Cambridge (they/them) [:kitcambridge] from comment #3)
> Could you please upload the entire `weave` folder from that profile?
> I'd especially like to see the logs and `bookmarks.sqlite`.

For some reason there's no bookmarks.sqlite in that .zip file - but the logs are, which has pointers to what went wrong. I started looking for low fruit - specifically "Child record ${GUID} appears as a child in multiple parents"

In the first case I looked at, the bookmarks in question appear to be the default Nightly bookmarks - so we have both local and remote structures that look like:

menu
 + Nightly Resources
   + Discuss Nightly on IRC

It appears as though the account had a different profile upload it's copy of this structure to the server and locally we have the same structure but with different GUIDs.

I *think* I've reproduced this issue with the following test - however, the test runner doesn't appear to have TRACE logs. The failure of this new test is:

> 0:00.80 INFO "Expected structure for root________: ...
> 0:00.80 INFO "Actual structure for root________: {"guid":"root________",...,"children":[{"guid":"menu________","children":[{"guid":"folderAAAAA2","index":0,"title":"A","type":2},{"guid":"folderAAAAA1",...

(where folderAAAAA1 should have been deduped to folderAAAAA2)
 
The logs I see from Kanchan's logs show something like:

2018-02-08 11:49:45.229000 (00:01:21.495)	Sync.Engine.Bookmarks.Mirror	TRACE	Merging local child "__PARENT2__ (F; 782.738s; !)" of "menu________ (F; 780.041s; !)" into "menu________ (V: L; S: L)"
2018-02-08 11:49:45.229000 (00:01:21.495)	Sync.Engine.Bookmarks.Mirror	TRACE	Item __PARENT2__ only exists locally as "__PARENT2__ (F; 782.738s; !)"; taking local state
2018-02-08 11:49:45.229000 (00:01:21.495)	Sync.Engine.Bookmarks.Mirror	TRACE	Merging local children of "__PARENT2__ (F; 782.738s; !)" into "__PARENT2__ (V: L; S: L)"
2018-02-08 11:49:45.230000 (00:01:21.496)	Sync.Engine.Bookmarks.Mirror	TRACE	Merge state for "__PARENT2__ (V: L; S: L)" has new structure "(V: L; S: +)"
2018-02-08 11:49:45.230000 (00:01:21.496)	Sync.Engine.Bookmarks.Mirror	TRACE	Not deduping "__PARENT2__ (F; 782.738s; !)"; already seen in another folder

Where that "Not deduping __PARENT2__" entry appears many many times and seems to be the underlying cause.

Kit, does that test look sane, and if so, any thoughts on what might have gone wrong. At first glance it looks a little like we are merging top-down rather than bottom-up. I'm also not yet sure if this is the only problem here, so I'm keeping my ni? open.
Flags: needinfo?(kit)
Posted patch t.patchSplinter Review
oops - unsaved changes in my editor FTW!
Attachment #8951143 - Attachment is obsolete: true
Another bizarre validation error I see is:

Record aLLoG6_FUGUq has structural differences (fields: ["parentid"]) between local and server copies. The local record has "unfiled" while the server has "r1rFCGrtecJr".

Relevant log entries:

> TRACE	Storing bookmark in mirror: {"id":"aLLoG6_FUGUq","type":"bookmark","parentid":"r1rFCGrtecJr"
(so it's on the server with the parent we expect)

> TRACE	Merging remote child "aLLoG6_FUGUq (B; 24968.030s; !)" of "r1rFCGrtecJr (F; 24968.030s; !)" into "r1rFCGrtecJr (V: R; S: R)"
> TRACE	Remote child "aLLoG6_FUGUq (B; 24968.030s; !)" doesn't exist locally; looking for content match

(so it's a new item that doesn't exist locally)

> TRACE	Merged node "r1rFCGrtecJr (V: R; S: R)" doesn't exist locally; no potential dupes for "aLLoG6_FUGUq (B; 24968.030s; !)"
> TRACE	Item aLLoG6_FUGUq only exists remotely as "aLLoG6_FUGUq (B; 24968.030s; !)"; taking remote state

(so we seem to know where it should go)

> TRACE	Built new merged tree
<snip lines that shows the item is correctly parented in the new merged tree>

> TRACE	Built remote tree from mirror
<snip lines that shows the item is correctly parented in the remote tree>

> TRACE	Built local tree from Places
<snip lines that shows it is/will-be correctly parented locally>

and that's the last log entry for that item - however, the validator reports it is in "unfiled". There's no evidence in the logs of a relationship between that item and "unfiled" at all!
Depends on: 1438740
(In reply to Mark Hammond [:markh] from comment #6)
> I started playing with this a little and thought I'd share what I have now
> to see if Kit has any thoughts.

Thanks for digging into this, Mark!

> I *think* I've reproduced this issue with the following test - however, the
> test runner doesn't appear to have TRACE logs.

You can enable trace logging if you flip https://searchfox.org/mozilla-central/rev/74b7ffee403c7ffd05b8b476c411cbf11d134eb9/toolkit/components/places/tests/sync/head_sync.js#15. I wonder if we should enable it by default.

> Kit, does that test look sane, and if so, any thoughts on what might have
> gone wrong.

Two things are a bit off, and you also caught a bug!

* The server record for `bookmarkGGG2` should have `bmkUri: "http://example.com/g"`, not `url: "http://example.com/g"`...which I also goofed in `test_duping` below. ^_^ It works in `test_duping` because, even though the mirror is out of sync, we have `bookmarkGGGG` locally. In both cases, the missing `bmkUri` causes us to ignore `bookmarkGGG2` entirely; if you turn on trace logging, you'll see `Ignoring bookmark bookmarkGGG2 with invalid URL undefined` and `Remote tree missing items: ["bookmarkGGG2"]`. So `bookmarkGGG2` doesn't show up in our remote tree, and we don't dedupe `bookmarkGGG1`.

* We should pass `{ needsMerge: true }`. `needsMerge = false` flags the records as unmodified in the mirror, indicating we already merged them into Places at some point in the past. (We do this when we write uploaded records back to the mirror: https://searchfox.org/mozilla-central/rev/74b7ffee403c7ffd05b8b476c411cbf11d134eb9/services/sync/modules/engines/bookmarks.js#828). Rows where `needsMerge = false` aren't candidates for deduping, because we must have previously applied them. I filed bug 1438740 to add a consistency check for this: if we have rows in the mirror that don't exist at all in Places, but where `needsMerge = false`, or if we have rows in Places with `syncStatus = NORMAL` that don't exist in the mirror, our mirror is out of sync.

With both those fixed, your test passes for me. But I haven't dug any deeper than that to understand why the deduping logic isn't kicking in. :-/ Keeping my ni? for tomorrow.
Blocks: 1433177
Flags: needinfo?(kit)
I see what's happening here. It's a regression from bug 1435553.

> 1518050979525 Sync.Engine.Bookmarks.Mirror  TRACE Storing query in mirror: {"id":"UqlGvhStjclq","type":"query","parentid":"menu","parentName":"Bookmarks Menu","dateAdded":1518024743195,"title":"Recent Tags","bmkUri":"place:type=6&sort=14&maxResults=10","queryId":"RecentTags","hasDupe":true}
> 1518050985202 Sync.Engine.Bookmarks.Mirror  TRACE Built local tree from Places
> + root________ (F; 0.000s)
> | + menu________ (F; 780.041s; !)
> | | - OnRuBEFsWJcj (Q; 780.043s; !)

So, "UqlGvhStjclq" is "Recent Tags" on the server; "OnRuBEFsWJcj" is "Recent Tags" locally.

> 1518050985228 Sync.Engine.Bookmarks.Mirror  TRACE Item menu________ exists locally as "menu________ (F; 780.041s; !)" and remotely as "menu________ (F; 19131.160s; !)"; merging

The local menu is newer than the remote menu, so we start with its children first.

> 1518050985228 Sync.Engine.Bookmarks.Mirror  TRACE Merging local child "OnRuBEFsWJcj (Q; 780.043s; !)" of "menu________ (F; 780.041s; !)" into "menu________ (V: L; S: L)"
> 1518050985229 Sync.Engine.Bookmarks.Mirror  TRACE Item OnRuBEFsWJcj only exists locally as "OnRuBEFsWJcj (Q; 780.043s; !)"; taking local state

We finish merging all local children, and move on to remote. *However*, we don't look for content matches when we merge local nodes. By the time we walk new remote children, we've already added all local children to our merge tree, even though they might be dupes of remote children we haven't seen yet!

> 1518050985230 Sync.Engine.Bookmarks.Mirror  TRACE Merging remote child "UqlGvhStjclq (Q; 24968.030s; !)" of "menu________ (F; 19131.160s; !)" into "menu________ (V: L; S: L)"
> 1518050985230 Sync.Engine.Bookmarks.Mirror  TRACE Remote child "UqlGvhStjclq (Q; 24968.030s; !)" doesn't exist locally; looking for content match
> 1518050985230 Sync.Engine.Bookmarks.Mirror  TRACE Not deduping "OnRuBEFsWJcj (Q; 780.043s; !)"; already seen in another folder

I think we'll want a matching `findRemoteNodeMatchingLocalNode` method. This is also a good opportunity to clean up our deduping; in particular, Thom noticed a few weeks back that we repeatedly loop over the parent's children (https://searchfox.org/mozilla-central/rev/44fa24847e4e73ce8932de4c8cf47559302e4ba2/toolkit/components/places/SyncedBookmarksMirror.jsm#4136).
Flags: needinfo?(markh)
Assignee: nobody → kit
Status: NEW → ASSIGNED
Comment on attachment 8957830 [details]
Bug 1436888 - Look for remote bookmark dupes when merging local children.

I'd like to get the test in a better shape, but does the general idea seem sensible?
Attachment #8957830 - Flags: feedback?(tchiovoloni)
Attachment #8957830 - Flags: feedback?(markh)

Comment 13

Last year
mozreview-review
Comment on attachment 8957830 [details]
Bug 1436888 - Look for remote bookmark dupes when merging local children.

https://reviewboard.mozilla.org/r/226814/#review232812

Looks good but I'd like to see this again after the change to the nested loop discussed in IRC. Some of my comments will not matter anymore after that also.

::: toolkit/components/places/SyncedBookmarksMirror.jsm:4086
(Diff revision 1)
> -   * @param  {MergedBookmarkNode} mergedNode
> -   *         The merged folder node.
> -   * @param  {BookmarkNode} remoteChildNode
> -   *         The remote child node.
> -   * @return {BookmarkNode?}
> -   *         A matching local child node, or `null` if there are no matching
> +   * This method is called the first time that `findRemoteNodeMatchingLocalNode`
> +   * merges a local child that doesn't exist remotely, and the first time that
> +   * `findLocalNodeMatchingRemoteNode` merges a remote child that doesn't exist
> +   * locally.
> +   *
> +   * Determining all possible dupes is O(n^2) in the worst case, but we cache

As discussed in IRC this is really O(nm) every time, not just worst case.

::: toolkit/components/places/SyncedBookmarksMirror.jsm:4097
(Diff revision 1)
> +   * know the structure yet. Without the structure, we can only match by GUID or
> +   * parent name and content. Matching by GUID means the node exists on both
> +   * sides, so we don't need to dedupe at all. Matching by parent name might
> +   * smush remote and local children in unrelated subtrees.
> +   *
> +   * For example, consider the local subtrees `Menu > A > B > C`

As we discussed in IRC, some parts of this comment are probably better placed elsewhere. I'll let you use your judgement though, I'd rather have them than not, so in the worst case you can just drop the issue and leave them here.

::: toolkit/components/places/SyncedBookmarksMirror.jsm:4117
(Diff revision 1)
> +   *          remote children to local children.
> +   *          `findRemoteNodeMatchingLocalNode` looks up matching remote
> +   *          children by local node. `findLocalNodeMatchingRemoteNode` looks up
> +   *          local children by remote node.
>     */
> -  async findLocalNodeMatchingRemoteNode(mergedNode, remoteChildNode) {
> +  async findAllMatchingDupesInFolders(localParentNode, remoteParentNode) {

As discussed in IRC, this can be done in O(n + m) without really a lot of extra work so we should do that. If you decide otherwise, probably open up a followup.

::: toolkit/components/places/SyncedBookmarksMirror.jsm:4139
(Diff revision 1)
>        if (this.remoteTree.isDeleted(localChildNode.guid)) {
>          MirrorLog.trace("Not deduping ${localChildNode}; deleted on server",
>                          { localChildNode });
>          continue;
>        }
> -      let localChildContent = this.newLocalContents.get(localChildNode.guid);
> +      for await (let remoteChildNode of remoteParentNode.children) {

I think you meant to use yieldingIterator here? (otherwise it's a for await over a synchronous iterator).

::: toolkit/components/places/SyncedBookmarksMirror.jsm:4140
(Diff revision 1)
>          MirrorLog.trace("Not deduping ${localChildNode}; deleted on server",
>                          { localChildNode });
>          continue;
>        }
> -      let localChildContent = this.newLocalContents.get(localChildNode.guid);
> +      for await (let remoteChildNode of remoteParentNode.children) {
> +        if (matches.has(localChildNode) || matches.has(remoteChildNode)) {

Nit: Unless we expect to write it into matches and then check again (which I *think* we don't expect), can you move the `matches.has(localChildNode)` to the parent loop, since it shouldn't change?

LMK if I'm misreading it though and that would break correctness.

Updated

Last year
Priority: -- → P1
Comment on attachment 8957830 [details]
Bug 1436888 - Look for remote bookmark dupes when merging local children.

F+ to get it out of my queue and because its basically there.
Attachment #8957830 - Flags: feedback?(tchiovoloni) → feedback+
Assignee

Comment 15

Last year
mozreview-review-reply
Comment on attachment 8957830 [details]
Bug 1436888 - Look for remote bookmark dupes when merging local children.

https://reviewboard.mozilla.org/r/226814/#review232812

Thanks for the excellent feedback, Thom!
Comment hidden (mozreview-request)
The discussion about the GUID map in the comment above `findAllMatchingDupesInFolders` was distracting. It's a historical tangent on why deduping works the way it does, which might be useful to capture in docs, but probably not there. Pasting it here for future reference, until we have a better place for Sync docs:

> We can't determine dupes before building the merged tree, because we don't
> know the structure yet. Without the structure, we can only match by GUID or
> parent name and content. Matching by GUID means the node exists on both
> sides, so we don't need to dedupe at all. Matching by parent name might
> smush remote and local children in unrelated subtrees.
> 
> For example, consider the local subtrees `Menu > A > B > C`
> and `Toolbar > AA > BB > CC`, and remote subtrees `Menu > A1 > B1 > C1` and
> `Toolbar > AA1 > BB1 > CC1`, where all nodes have matching content.
> 
> Deduping by parent name might match B1 to B (right) *or* BB (wrong), C1 to
> C (right) *or* CC (wrong), BB1 to BB (right) *or* B (wrong), and CC1 to
> CC (right) *or* C (wrong), or any combinations of these.

I also removed "most users have shallow trees with few folders, so the cost is amortized", because citation needed, and https://imgur.com/a/acEoS. ;-)

Comment 18

Last year
mozreview-review
Comment on attachment 8957830 [details]
Bug 1436888 - Look for remote bookmark dupes when merging local children.

https://reviewboard.mozilla.org/r/226814/#review233722

::: toolkit/components/places/SyncedBookmarksMirror.jsm:4333
(Diff revision 2)
>                        { mergedNode, remoteChildNode });
>        return null;
>      }
> -    let remoteChildContent = this.newRemoteContents.get(remoteChildNode.guid);
> -    if (!remoteChildContent) {
> -      // The node doesn't exist locally, but it's also flagged as merged in the
> +    let remoteParentNode = mergedNode.remoteNode;
> +    if (!remoteParentNode) {
> +      // Should never happen. The remote tree must be complete.

It's not clear to me if "Should never happen" refers to the local logic, or to the state of the remote tree. If the latter, this seems quite fatal and I'm not sure throwing is the right thing to do. If the former, then maybe clarifying the comment to reflect that we've previously done magic to make the remote tree complete might make sense
Attachment #8957830 - Flags: review?(markh) → review+
Assignee

Comment 19

Last year
mozreview-review-reply
Comment on attachment 8957830 [details]
Bug 1436888 - Look for remote bookmark dupes when merging local children.

https://reviewboard.mozilla.org/r/226814/#review233722

> It's not clear to me if "Should never happen" refers to the local logic, or to the state of the remote tree. If the latter, this seems quite fatal and I'm not sure throwing is the right thing to do. If the former, then maybe clarifying the comment to reflect that we've previously done magic to make the remote tree complete might make sense

It's more like an assertion. If we call `findLocalNodeMatchingRemoteNode` when we're not actually merging a remote folder, we're calling it incorrectly. I fixed the comments and error strings here and elsewhere, and switched to using `TypeError`, which I use for others like this.

(In other places, when we build a `BookmarkTree`, every node should have a parent. The remote tree in the miror might not, but those get moved to unfiled in `fetchRemoteTree`. If our in-memory tree has a node with no parent, we did something wrong when building it).

Good call!
Comment hidden (mozreview-request)

Comment 21

Last year
mozreview-review
Comment on attachment 8957830 [details]
Bug 1436888 - Look for remote bookmark dupes when merging local children.

https://reviewboard.mozilla.org/r/226814/#review234802

This looks great now, thanks!

::: toolkit/components/places/SyncedBookmarksMirror.jsm:2730
(Diff revision 3)
> + * @param  {BookmarkContent} content
> + *         Content info for the node.
> + * @return {String}
> + *         The lookup key.
> + */
> +function makeDupeKey(node, content) {

Can you add a comment somewhere explaining why we use JSON.stringify and not joining with a separator?
Attachment #8957830 - Flags: review?(tchiovoloni) → review+
Comment hidden (mozreview-request)

Comment 23

Last year
Pushed by kcambridge@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3fff2bcc9e0e
Look for remote bookmark dupes when merging local children. r=markh,tcsc
https://hg.mozilla.org/mozilla-central/rev/3fff2bcc9e0e
Status: ASSIGNED → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → Firefox 61
Reporter

Updated

Last year
Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.