747040 - After XUL profile migration, NPE on AndroidBrowserBookmarksRepositorySession.retrieveRecord

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Android Sync, defect, P1)

Description

[Tony Chung [:tchung]]

Attachment: logcat

After running through sync XUL->Native migration testing (see https://bugzilla.mozilla.org/show_bug.cgi?id=743098#c8 for STR), i'm seeing NullPointerException and sync aborting logs on bookmarksRepositorySession.

Additonal STR is to force sync, and is reproducible.

Full logcat attached.  

04-19 09:18:36.126: INFO/RecordsChannel(7918): Source session began. Beginning sink session.
04-19 09:18:36.157: INFO/BrowserRepoSession(7918): BEGIN: checking database.
04-19 09:18:36.165: INFO/BrowserRepoSession(7918): END: checking database.
04-19 09:18:36.165: INFO/RecordsChannel(7918): Sink session began. Beginning flow.
04-19 09:18:37.157: INFO/BrowserRepoSession(7918): BEGIN: creating record -> GUID map.
04-19 09:18:37.165: DEBUG/dalvikvm(7918): GC_CONCURRENT freed 1002K, 20% free 17834K/22087K, paused 2ms+6ms
04-19 09:18:37.243: ERROR/BrowserRepoSession(7918): No parent for record MZoyr8aQCjwq
04-19 09:18:37.243: WARN/BrowserRepoSession(7918): Bookmark record MZoyr8aQCjwq has a bad parent pointer. Reparenting now.
04-19 09:18:37.251: DEBUG/dalvikvm(7918): GC_CONCURRENT freed 1288K, 20% free 17830K/22087K, paused 2ms+4ms
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918): Store failed for menu
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918): java.lang.NullPointerException
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveRecord(AndroidBrowserBookmarksRepositorySession.java:437)
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveDuringStore(AndroidBrowserBookmarksRepositorySession.java:374)
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.createRecordToGuidMap(AndroidBrowserRepositorySession.java:625)
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.putRecordToGuidMap(AndroidBrowserRepositorySession.java:646)
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.updateBookkeeping(AndroidBrowserRepositorySession.java:655)
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.updateBookkeeping(AndroidBrowserBookmarksRepositorySession.java:672)
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.replace(AndroidBrowserRepositorySession.java:531)
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession$1.run(AndroidBrowserRepositorySession.java:469)
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1076)
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
04-19 09:18:37.259: ERROR/BrowserRepoSession(7918):     at java.lang.Thread.run(Thread.java:856)
04-19 09:18:37.259: WARN/SynchronizerSession(7918): First RecordsChannel onFlowStoreFailed. Reporting store error.
04-19 09:18:37.259: WARN/SynchronizerSession(7918): java.lang.NullPointerException
04-19 09:18:37.259: WARN/SynchronizerSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveRecord(AndroidBrowserBookmarksRepositorySession.java:437)
04-19 09:18:37.259: WARN/SynchronizerSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveDuringStore(AndroidBrowserBookmarksRepositorySession.java:374)
04-19 09:18:37.259: WARN/SynchronizerSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.createRecordToGuidMap(AndroidBrowserRepositorySession.java:625)
04-19 09:18:37.259: WARN/SynchronizerSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.putRecordToGuidMap(AndroidBrowserRepositorySession.java:646)
04-19 09:18:37.259: WARN/SynchronizerSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.updateBookkeeping(AndroidBrowserRepositorySession.java:655)
04-19 09:18:37.259: WARN/SynchronizerSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.updateBookkeeping(AndroidBrowserBookmarksRepositorySession.java:672)
04-19 09:18:37.259: WARN/SynchronizerSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.replace(AndroidBrowserRepositorySession.java:531)
04-19 09:18:37.259: WARN/SynchronizerSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession$1.run(AndroidBrowserRepositorySession.java:469)
04-19 09:18:37.259: WARN/SynchronizerSession(7918):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1076)
04-19 09:18:37.259: WARN/SynchronizerSession(7918):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
04-19 09:18:37.259: WARN/SynchronizerSession(7918):     at java.lang.Thread.run(Thread.java:856)
04-19 09:18:37.259: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.DefaultClientConnection(7918): Connection shut down
04-19 09:18:37.259: INFO/CRecordConsumer(7918): Consumer is done. Processed 1 record.
04-19 09:18:37.259: INFO/ServerSyncStage(7918): onSynchronizeAborted.
04-19 09:18:37.259: WARN/GlobalSession(7918): Aborting sync: Synchronization was aborted.
04-19 09:18:37.259: INFO/SyncAdapter(7918): GlobalSession indicated error. Flagging auth token as invalid, just in case.
04-19 09:18:37.259: INFO/SyncAdapter(7918): Notifying sync monitor.
04-19 09:18:37.267: WARN/GlobalSession(7918): Aborting sync: Got store error.
04-19 09:18:37.267: WARN/GlobalSession(7918): java.lang.NullPointerException
04-19 09:18:37.267: WARN/GlobalSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveRecord(AndroidBrowserBookmarksRepositorySession.java:437)
04-19 09:18:37.267: WARN/GlobalSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.retrieveDuringStore(AndroidBrowserBookmarksRepositorySession.java:374)
04-19 09:18:37.267: WARN/GlobalSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.createRecordToGuidMap(AndroidBrowserRepositorySession.java:625)
04-19 09:18:37.267: WARN/GlobalSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.putRecordToGuidMap(AndroidBrowserRepositorySession.java:646)
04-19 09:18:37.267: WARN/GlobalSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.updateBookkeeping(AndroidBrowserRepositorySession.java:655)
04-19 09:18:37.267: WARN/GlobalSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.updateBookkeeping(AndroidBrowserBookmarksRepositorySession.java:672)
04-19 09:18:37.267: WARN/GlobalSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.replace(AndroidBrowserRepositorySession.java:531)
04-19 09:18:37.267: WARN/GlobalSession(7918):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession$1.run(AndroidBrowserRepositorySession.java:469)
04-19 09:18:37.267: WARN/GlobalSession(7918):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1076)
04-19 09:18:37.267: WARN/GlobalSession(7918):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
04-19 09:18:37.267: WARN/GlobalSession(7918):     at java.lang.Thread.run(Thread.java:856)
04-19 09:18:37.267: INFO/SyncAdapter(7918): GlobalSession indicated error. Flagging auth token as invalid, just in case.
04-19 09:18:37.267: INFO/SyncAdapter(7918): Setting minimum next sync time to 1334852617267
04-19 09:18:37.298: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager(7918): Closing expired connections
04-19 09:18:37.298: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute(7918): Closing expired connections
04-19 09:18:37.298: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager(7918): Shutting down
04-19 09:18:37.298: INFO/SyncAdapter(7918): Notifying sync monitor.

Comment 1

[Richard Newman [:rnewman]]

This might mean there's a bug in profile migration, too, if it's migrating the Places root structure (which is wrong for Fennec), and we're handling it badly.

Will take a look at this trace in a little while.

Comment 2

[Gian-Carlo Pascutto [:gcp]]

Profile Migration reroots the Places DB with the Fennec roots:
https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/ProfileMigrator.java#561

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

There might be other stuff there though that we don't deal with.

Comment 3

[Richard Newman [:rnewman]]

What seems to be happening (blinded by lack of debug/trace logging in this capture, alas) is that one of the records in the database has a parent ID that is not the ID of a folder with a GUID.

That means one of:

* Its parent ID doesn't point to a valid record
* Its parent is not a folder
* Its parent has a null GUID.

I've got a patch to stop this causing an exception, but something seems to be awry here.

I'll know more when I get more logs and a DB snapshot from Tony.

Comment 4

[Richard Newman [:rnewman]]

Is it possible that the profile being migrated was old enough to contain real livemarks? That is, to have records whose parents are livemarks, not folders?

Comment 5

[Richard Newman [:rnewman]]

Trivial pull request to avoid an exception:

https://github.com/mozilla-services/android-sync/pull/171

Comment 6

[Tony Chung [:tchung]]

note to self: i owe rnewman a db dump of my phone profile.

Comment 7

[Richard Newman [:rnewman]]

Filed Bug 747181 to cover an apparent hole in migration.

The fix for this bug is a band-aid to avoid falling over in this instance. With said band-aid Sync will probably go right ahead and fix the data on first sync!

Comment 8

[Tony Chung [:tchung]]

(In reply to Tony Chung [:tchung] from comment #6)
> note to self: i owe rnewman a db dump of my phone profile.

just to follow up, i pastebin'd my verbose log to rnewman in irc.   dumpdbs.py is not supported for org.mozilla.fennec.

Comment 9

[Richard Newman [:rnewman]]

Trivial guard against NPE (all callers are null-check-safe, so this is fine):

https://hg.mozilla.org/integration/mozilla-inbound/rev/c5cb077b45c8

The real fix will come from Bug 747181, which margaret fixed and I just reviewed.

Comment 10

[Phil Ringnalda (:philor)]

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