747181 - Profile migration migrates tag folders

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Richard Newman [:rnewman]]

Sync log arising from Bug 747040:

----
Check and build special GUIDs.
Got GUIDs for folders.
Preparing folder ID mappings.
Tracking places root as ID 0.
GUID mobile maps to 1
GUID 8wPJA4H7VFRY maps to 22
GUID doLx8Lg0tKVG maps to 72
GUID pS-uOgmmya-c maps to 1216
GUID 3LDL0PAUKTLV maps to 1475
GUID toolbar maps to 2
GUID -VCQzaUVaMH0 maps to 24
GUID HLbvVlDX_N-x maps to 74
GUID PDDPM1_KYjgh maps to 622
GUID fKpyKshrxGto maps to 992
GUID menu maps to 3
GUID O01VYJKK4-97 maps to 64
GUID I0eNJM3rD8eY maps to 75
GUID bt9ZklQdKkLI maps to 1499
GUID Hq-ZM5yGQYio maps to 10
GUID wZoW5rLZ4KoH maps to 112
GUID q6MG271s4Zn6 maps to 1231
GUID qEUxqLu5fCyh maps to 1234
GUID unfiled maps to 5
GUID n5qF3nMLuYVx maps to 115
GUID zCrD2f0pFHma maps to 1424
GUID 8s6ATlNbbM5p maps to 1452
GUID eB7p0buFWjgz maps to 117
GUID WeMvl2Km8K-2 maps to 207
GUID OJLc2DtYf-Vt maps to 208
GUID 6ltvQmFxDU_c maps to 209
GUID 7-pH7saTeFnh maps to 210
GUID G2WzC4ZnuTBG maps to 414
GUID v4yt1avgSE2V maps to 283
GUID o50KUNrB16An maps to 529
GUID HNpWt23_xyVL maps to 449
GUID 1AgPcQfQKPG0 maps to 570
GUID E0JKfiSqBB-a maps to 782
GUID X42uMNzMVd83 maps to 791
GUID QKT4WEMQ7AHF maps to 783
GUID p5SmZ3QwF8Dr maps to 1206
GUID CUbP1pu-FcjR maps to 798
GUID JeF9BLRww5Kj maps to 799
GUID DvwG2WTd-8LQ maps to 873
GUID otHerpRk_hPu maps to 1118
GUID m3c32VZL1bci maps to 1119
GUID DCS7FKeoEa3O maps to 361
GUID VEAHHOryb1xE maps to 746
GUID jVIeU_HNfjqD maps to 1085
GUID pRbCAeLGvdPQ maps to 1215
Done with initial setup of bookmarks session.

...

No parent GUID for record 8wPJA4H7VFRY with parent 4
----

Sync starts by building a mapping from all folders to their IDs, along with places = 0.

We then attempt to make mappings from a string representation of each record to the record's GUID. That string representation requires the parent.

It's walking this cursor that we blow up.

When querying the database, Sync grabs a record with GUID 8wPJA4H7VFRY and parent 4. Note that in the query for all folders in the database, there is not one with ID 4. It goes 1, 2, 3, 5.

We then die with a NPE (easy to fix), but this probably means that there's an error in translating the data.

Comment 1

[Tony Chung [:tchung]]

The NPE following output in comment 0:

04-19 14:17:23.768 E/BrowserRepoSession(18697): Store failed for menu
04-19 14:17:23.768 E/BrowserRepoSession(18697): java.lang.NullPointerException
04-19 14:17:23.768 E/BrowserRepoSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveRecord(AndroidBrowserBookmarksRepositorySession.java:437)
04-19 14:17:23.768 E/BrowserRepoSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveDuringStore(AndroidBrowserBookmarksRepositorySession.java:374)
04-19 14:17:23.768 E/BrowserRepoSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.createRecordToGuidMap(AndroidBrowserRepositorySession.java:625)
04-19 14:17:23.768 E/BrowserRepoSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.putRecordToGuidMap(AndroidBrowserRepositorySession.java:646)
04-19 14:17:23.768 E/BrowserRepoSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.updateBookkeeping(AndroidBrowserRepositorySession.java:655)
04-19 14:17:23.768 E/BrowserRepoSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.updateBookkeeping(AndroidBrowserBookmarksRepositorySession.java:672)
04-19 14:17:23.768 E/BrowserRepoSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.replace(AndroidBrowserRepositorySession.java:531)
04-19 14:17:23.768 E/BrowserRepoSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession$1.run(AndroidBrowserRepositorySession.java:469)
04-19 14:17:23.768 E/BrowserRepoSession(18697): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1088)
04-19 14:17:23.768 E/BrowserRepoSession(18697): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:581)
04-19 14:17:23.768 E/BrowserRepoSession(18697): 	at java.lang.Thread.run(Thread.java:1027)
04-19 14:17:23.768 W/SynchronizerSession(18697): First RecordsChannel onFlowStoreFailed. Reporting store error.
04-19 14:17:23.768 W/SynchronizerSession(18697): java.lang.NullPointerException
04-19 14:17:23.768 W/SynchronizerSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveRecord(AndroidBrowserBookmarksRepositorySession.java:437)
04-19 14:17:23.768 W/SynchronizerSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveDuringStore(AndroidBrowserBookmarksRepositorySession.java:374)
04-19 14:17:23.768 W/SynchronizerSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.createRecordToGuidMap(AndroidBrowserRepositorySession.java:625)
04-19 14:17:23.768 W/SynchronizerSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.putRecordToGuidMap(AndroidBrowserRepositorySession.java:646)
04-19 14:17:23.768 W/SynchronizerSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.updateBookkeeping(AndroidBrowserRepositorySession.java:655)
04-19 14:17:23.768 W/SynchronizerSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.updateBookkeeping(AndroidBrowserBookmarksRepositorySession.java:672)
04-19 14:17:23.768 W/SynchronizerSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.replace(AndroidBrowserRepositorySession.java:531)
04-19 14:17:23.768 W/SynchronizerSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession$1.run(AndroidBrowserRepositorySession.java:469)
04-19 14:17:23.768 W/SynchronizerSession(18697): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1088)
04-19 14:17:23.768 W/SynchronizerSession(18697): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:581)
04-19 14:17:23.768 W/SynchronizerSession(18697): 	at java.lang.Thread.run(Thread.java:1027)
04-19 14:17:23.768 D/class ch.boye.httpclientandroidlib.impl.conn.DefaultClientConnection(18697): Connection shut down
04-19 14:17:23.788 I/ServerSyncStage(18697): onSynchronizeAborted.
04-19 14:17:23.788 I/CRecordConsumer(18697): Consumer is done. Processed 1 record.
04-19 14:17:23.788 W/GlobalSession(18697): Aborting sync: Synchronization was aborted.
04-19 14:17:23.788 I/SyncAdapter(18697): GlobalSession indicated error. Flagging auth token as invalid, just in case.
04-19 14:17:23.798 I/SyncAdapter(18697): Notifying sync monitor.
04-19 14:17:23.798 I/SyncAdapter(18697): Setting minimum next sync time to 1334870543806
04-19 14:17:23.798 W/GlobalSession(18697): Aborting sync: Got store error.
04-19 14:17:23.798 W/GlobalSession(18697): java.lang.NullPointerException
04-19 14:17:23.798 W/GlobalSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveRecord(AndroidBrowserBookmarksRepositorySession.java:437)
04-19 14:17:23.798 W/GlobalSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveDuringStore(AndroidBrowserBookmarksRepositorySession.java:374)
04-19 14:17:23.798 W/GlobalSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.createRecordToGuidMap(AndroidBrowserRepositorySession.java:625)
04-19 14:17:23.798 W/GlobalSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.putRecordToGuidMap(AndroidBrowserRepositorySession.java:646)
04-19 14:17:23.798 W/GlobalSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.updateBookkeeping(AndroidBrowserRepositorySession.java:655)
04-19 14:17:23.798 W/GlobalSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.updateBookkeeping(AndroidBrowserBookmarksRepositorySession.java:672)
04-19 14:17:23.798 W/GlobalSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.replace(AndroidBrowserRepositorySession.java:531)
04-19 14:17:23.798 W/GlobalSession(18697): 	at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession$1.run(AndroidBrowserRepositorySession.java:469)
04-19 14:17:23.798 W/GlobalSession(18697): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1088)
04-19 14:17:23.798 W/GlobalSession(18697): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:581)
04-19 14:17:23.798 W/GlobalSession(18697): 	at java.lang.Thread.run(Thread.java:1027)
04-19 14:17:23.798 I/SyncAdapter(18697): GlobalSession indicated error. Flagging auth token as invalid, just in case.
04-19 14:17:24.038 D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager(18697): Closing expired connections
04-19 14:17:24.038 D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute(18697): Closing expired connections
04-19 14:17:24.038 D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager(18697): Shutting down
04-19 14:17:24.048 I/SyncAdapter(18697): Notifying sync monitor.

Comment 2

[Aaron Train [:aaronmt]]

Repro steps easy enough to block?

Comment 3

[Richard Newman [:rnewman]]

In my profile, record 4 is tags, which we don't support, and don't regard as a folder. But its children are folders. Perhaps profile migration is migrating the tags folder?

Comment 4

[Richard Newman [:rnewman]]

(In reply to Richard Newman [:rnewman] from comment #3)
> In my profile, record 4 is tags, which we don't support, and don't regard as
> a folder. But its children are folders. Perhaps profile migration is
> migrating the tags folder?

Pretty sure that's it. So we have a choice:

* Don't migrate the tags folders in the DB, because they're meaningless in Fennec now, and Sync doesn't want them
* Make Sync aware of the migrated tags folder so that it can ignore those records.

Comment 5

[Richard Newman [:rnewman]]

Should be trivial to repro:

* Blank profile
* Tag a bookmark
* Verify tag folder appears under "Tags" in Show Bookmarks
* Sync to XUL Fennec
* Migrate to Native Fennec.

gcp, mobile folks: would you rather preserve this (stale) data in the DB, and skip over it, or drop it during or after profile migration?

Comment 6

[Richard Newman [:rnewman]]

Arguments for doing this work in the migrator: Fennec shouldn't import records that it doesn't manage correctly (and tags is such); avoids redundant rows in the database; avoids need for UI to perhaps adapt to this.

Arguments against: don't want to touch migration code in the run up to beta; want to keep these rows around for some reason; excessive complexity in migration.

Comment 7

[Gian-Carlo Pascutto [:gcp]]

In BrowserProvider.in, we do create a TAGS root folder in createOrUpdateSpecialFolder, and actually check for it in some places:

https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/db/BrowserProvider.java.in#537

A typical log shows Profile Migrator rerooting to it:

04-19 09:06:06.439: VERBOSE/ProfileMigrator(7918): Name: places, pid=1, nid=0
04-19 09:06:06.454: VERBOSE/ProfileMigrator(7918): Name: menu, pid=2, nid=3
04-19 09:06:06.454: VERBOSE/ProfileMigrator(7918): Name: toolbar, pid=3, nid=2
04-19 09:06:06.462: VERBOSE/ProfileMigrator(7918): Name: tags, pid=4, nid=4  <---
04-19 09:06:06.462: VERBOSE/ProfileMigrator(7918): Name: unfiled, pid=5, nid=5

So there are 2 questions here for me:

1) I think we have a bug in that TAGS should be removed from the Fennec DB, based on your comment 3 and 4. We'd then have to special case this in the Profile Migrator (sounds acceptable, after all removing tags is a schema change and that is what ProfMigr is for).

2) Based on this, folder 4 shouldn't have been orphaned. i.e. where did the folder go in your comment 1? If it didn't exist when it ran, Profile Migration would have rerooted all tag folders to folder 0 (FIXED_ROOT_ID) and you wouldn't have seen this bug.

Comment 8

[Richard Newman [:rnewman]]

(In reply to Gian-Carlo Pascutto (:gcp) from comment #7)

> 1) I think we have a bug in that TAGS should be removed from the Fennec DB,
> based on your comment 3 and 4. We'd then have to special case this in the
> Profile Migrator (sounds acceptable, after all removing tags is a schema
> change and that is what ProfMigr is for).

If they're not being used and maintained by Fennec, this seems like the best approach.

If you think they *will* be used and maintained by Fennec, then by all means keep them, but that does imply a follow-up set of bugs to keep that tags hierarchy up-to-date and translate to and from the JSON encoding, or otherwise change that. Not sure anyone wants to commit to that work.

I'd be happy with a deletion of everything under tags (always a two-level hierarchy) at the end of migration, rather than complicating the mid-migration flow. We know a sync can't happen in the middle.

(In a perfect world you'll migrate to the tags JSON attribute on the main bookmark entry when tags exist, but that's probably more work than it's worth.)

> 2) Based on this, folder 4 shouldn't have been orphaned. i.e. where did the
> folder go in your comment 1? If it didn't exist when it ran, Profile
> Migration would have rerooted all tag folders to folder 0 (FIXED_ROOT_ID)
> and you wouldn't have seen this bug.

It was explicitly ignored in our folder query, just like the places root itself -- we only query for folders that we want to handle.

  protected Cursor getGuidsIDsForFolders() throws NullCursorException {
    // Exclude "places" and "tags", in case they've ended up in the DB.
    String where = BOOKMARK_IS_FOLDER + " AND " + GUID_NOT_TAGS_OR_PLACES;
    return queryHelper.safeQuery(".getGuidsIDsForFolders", GUID_AND_ID, where, null, null);
  }

Until now that's been fine, because Fennec doesn't have a way to create tag folders, and desktop Sync also deliberately ignores tags. The tags record in the Fennec DB is a kind of placeholder.

This led to the situation of Sync processing a folder (a tag folder) with a parent that we explicitly don't want to handle (and thus don't know about), which I confused with a folder with an unknown parent, because at that point in the code there's no difference!

Tags didn't occur to me until Comment 3 :D

Comment 9

[Mark Finkle (:mfinkle) (use needinfo?)]

Margaret - GCP is out for the next few days, so we need someone to take a look at this. Lucas is working on some other DB bugs.

Comment 10

[Gian-Carlo Pascutto [:gcp]]

Suggested approach: remember the "tags" new root during calculateReroot, then remove it from the list of known parent folders. This should cause them to be treated as orphaned bookmarks.

Comment 11

[Richard Newman [:rnewman]]

(In reply to Gian-Carlo Pascutto (:gcp) from comment #10)
> Suggested approach: remember the "tags" new root during calculateReroot,
> then remove it from the list of known parent folders. This should cause them
> to be treated as orphaned bookmarks.

That will result in a folder being added for each tag. Kill all the children, I think; the children of 'tags' are all folders named by a tag, and then their children are all bookmarks whose fk is a place that is _already referenced_ by a bookmark somewhere else in a tree.

That is, each tag folder contains clone bookmarks.

Comment 12

[Gian-Carlo Pascutto [:gcp]]

>That will result in a folder being added for each tag.

Huh? No, it should cause them not to be added as all. Orphaned bookmarks (including folders) aren't added - note that it's not even possible due the foreign key constraints we have in the new DB.

Comment 13

[Richard Newman [:rnewman]]

(In reply to Gian-Carlo Pascutto (:gcp) from comment #12)
> Orphaned bookmarks (including folders) aren't added

Oh, I see; I thought by "orphaned" you meant "moved into Unsorted Bookmarks". Yeah, that should do it then!

Comment 14

[:Margaret Leibovic]

Attachment: logcat

I started working on a patch for this, but found that the browser was crashing. After having a tough time figuring out what my patch could be doing, I tried building without my patch, and I still got the crash!

To test, I synced XUL fennec to a pretty clean test profile that has a tagged bookmark, then I tried installing my fennec native build.

I'll continue to look into this, but wanted to upload a log in case anyone has ideas (or if this is filed elsewhere).

Comment 15

[:Margaret Leibovic]

Attachment: WIP

I started out by trying to implement gcp's suggestion from comment 10, but then I thought it would be simpler to just avoid adding the tag folders, at least for code clarity (although I guess the tag folders' children will be deleted via the orphaning logic).

Comment 16

[Richard Newman [:rnewman]]

(In reply to Margaret Leibovic [:margaret] from comment #14)

> I'll continue to look into this, but wanted to upload a log in case anyone
> has ideas (or if this is filed elsewhere).

That constraint failure means that profile migrator is trying to add a record that already exists, or one with a null guid. If you're adding to a totally empty DB, it must be the latter, or your DB to migrate has dupes...

Comment 17

[Richard Newman [:rnewman]]

Comment on attachment 617171 [details] [diff] [review]
WIP

Review of attachment 617171 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good! According to what I understand from gcp, this should work nicely.

::: mobile/android/base/ProfileMigrator.java
@@ +124,5 @@
>      private static final String ROOT_NAME      = "root_name";
>      private static final String ROOT_FOLDER_ID = "folder_id";
>  
> +    // We use this to ignore the tags folder during migration
> +    private static final String TAGS_FOLDER_NAME      = "tags";

I'd probably call this "ROOT_TAGS_FOLDER_NAME" or "TAGS_ROOT_FOLDER_NAME" to distinguish it from the actual name of the folder ("Tags").

@@ +650,5 @@
>                            + ", nid=" + mRerootMap.get(placesFolderId));
> +
> +                    // Keep track of the tags folder id so we can avoid
> +                    // migrating tags later.
> +                    if (name.equals(TAGS_FOLDER_NAME))

Reverse this for a teensy bit of NPE protection:

  TAGS_FOLDER_NAME.equals(name)

Comment 18

[Gian-Carlo Pascutto [:gcp]]

The constraint failure when updating Favicons is expected - you won't crash as Profile Migrator explicitly catches it. See:
https://bugzilla.mozilla.org/show_bug.cgi?id=716729#c15 and Bug 717428.

Patch looks good to me.

Comment 19

[:Margaret Leibovic]

Attachment: patch

Thanks for the comments about the stack I was seeing.

Today, when I was less tired, I was able to verify that this does work. I used the following steps to verify:
-made a new profile/sync account on desktop
-added a tagged bookmark
-synced to XUL fennec
-verified that there was a tag folder and its child in places.sqlite
-installed native fennec
-watched migration run
-verified that tag folder and its child were missing from browser.db

As a real sanity check, I did the same steps without my patch, and the tag folder and its child did migrate as expected.

Comment 20

[Richard Newman [:rnewman]]

Comment on attachment 617256 [details] [diff] [review]
patch

Review of attachment 617256 [details] [diff] [review]:
-----------------------------------------------------------------

Code looks great.

I don't see any profile migration tests in mobile/android, so I doubt I can request any here, but I'll make sure this is flagged as qa+ and in-litmus? after clicking "Publish".

Thanks, Margaret!

::: mobile/android/base/ProfileMigrator.java
@@ +123,5 @@
>          "SELECT root_name, folder_id FROM moz_bookmarks_roots";
>      private static final String ROOT_NAME      = "root_name";
>      private static final String ROOT_FOLDER_ID = "folder_id";
>  
> +    // We use this to ignore the tags folder during migration

Nit: closing period.

Comment 21

[:Margaret Leibovic]

https://hg.mozilla.org/integration/mozilla-inbound/rev/1f4f4d6466b6

Comment 22

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/1f4f4d6466b6