Closed Bug 747040 Opened 7 years ago Closed 7 years ago

After XUL profile migration, NPE on AndroidBrowserBookmarksRepositorySession.retrieveRecord

Categories

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

ARM
Android
defect

Tracking

()

RESOLVED FIXED
mozilla14
Tracking Status
blocking-fennec1.0 --- beta+

People

(Reporter: tchung, Assigned: rnewman)

References

Details

Attachments

(1 file)

Attached file 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.
blocking-fennec1.0: --- → ?
OS: Mac OS X → Android
Hardware: x86 → ARM
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.
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.
Priority: -- → P1
Assignee: nobody → rnewman
Status: NEW → ASSIGNED
Summary: after sync xul migration, NPE on AndroidBrowserBookmarksRepositorySession.retrieveRecord → After XUL profile migration, NPE on AndroidBrowserBookmarksRepositorySession.retrieveRecord
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.
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?
Trivial pull request to avoid an exception:

https://github.com/mozilla-services/android-sync/pull/171
note to self: i owe rnewman a db dump of my phone profile.
Depends on: 747181
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!
(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.
blocking-fennec1.0: ? → beta+
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.
Target Milestone: --- → mozilla14
https://hg.mozilla.org/mozilla-central/rev/c5cb077b45c8
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Product: Mozilla Services → Android Background Services
Product: Android Background Services → Firefox for Android
You need to log in before you can comment on or make changes to this bug.