718194 - Mobile bookmark has null parent

Status: VERIFIED FIXED

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

Description

[Tony Chung [:tchung]]

Attachment: logcat

I hit this log when toggling the sync checkbox off and on.  

See logcat attachment for the whole thing.

01-14 08:40:46.683: INFO/DBUtils(28376): Query timer: AndroidBrowserRepositoryDataAccessor.fetch took 7ms.
01-14 08:40:46.683: DEBUG/AndroidBrowserRepositorySession(28376): Record from mirror cursor: SLaTXr7zXnd3
01-14 08:40:46.683: DEBUG/AndroidBrowserRepositorySession(28376):   1 => null
01-14 08:40:46.683: DEBUG/AndroidBrowserRepositorySession(28376): No parent GUID for record SLaTXr7zXnd3 with parent 1
01-14 08:40:46.683: DEBUG/AndroidBrowserRepositorySession(28376): Record SLaTXr7zXnd3 is a bookmark.
01-14 08:40:46.683: ERROR/DBUtils(28376): No parent for record SLaTXr7zXnd3
01-14 08:40:46.690: DEBUG/DBUtils(28376): Exception logging bookmark record null
01-14 08:40:46.690: DEBUG/DBUtils(28376): java.lang.NullPointerException
01-14 08:40:46.690: DEBUG/DBUtils(28376):     at org.mozilla.gecko.sync.repositories.android.RepoUtils.logBookmark(RepoUtils.java:286)
01-14 08:40:46.690: DEBUG/DBUtils(28376):     at org.mozilla.gecko.sync.repositories.android.RepoUtils.bookmarkFromMirrorCursor(RepoUtils.java:281)
01-14 08:40:46.690: DEBUG/DBUtils(28376):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.recordFromMirrorCursor(AndroidBrowserBookmarksRepositorySession.java:231)
01-14 08:40:46.690: DEBUG/DBUtils(28376):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.recordForGUID(AndroidBrowserRepositorySession.java:439)
01-14 08:40:46.690: DEBUG/DBUtils(28376):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession.findExistingRecord(AndroidBrowserRepositorySession.java:459)
01-14 08:40:46.690: DEBUG/DBUtils(28376):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession$1.run(AndroidBrowserRepositorySession.java:382)
01-14 08:40:46.690: DEBUG/DBUtils(28376):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1076)
01-14 08:40:46.690: DEBUG/DBUtils(28376):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
01-14 08:40:46.690: DEBUG/DBUtils(28376):     at java.lang.Thread.run(Thread.java:856)
01-14 08:40:46.690: DEBUG/AndroidBrowserRepositorySession(28376): Searching with record string Home - Sesame Streethttp://m.sesamestreet.org/bookmarkMobile Bookmarks
01-14 08:40:46.690: DEBUG/AndroidBrowserRepositorySession(28376): findExistingRecord failed to find one for SLaTXr7zXnd3
01-14 08:40:46.690: DEBUG/AndroidBrowserRepositorySession(28376): Inserting bookmark SLaTXr7zXnd3, Home - Sesame Street, http://m.sesamestreet.org/ with parent 29 (mobile, Mobile Bookmarks, null)
01-14 08:40:46.690: DEBUG/GeckoBrowserProvider(28376): Calling insert on URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
01-14 08:40:46.690: DEBUG/GeckoBrowserProvider(28376): Getting writable database for URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
01-14 08:40:46.690: DEBUG/GeckoBrowserProvider(28376): Beginning insert transaction: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
01-14 08:40:46.698: DEBUG/GeckoBrowserProvider(28376): Calling insert in transaction on URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
01-14 08:40:46.698: DEBUG/GeckoBrowserProvider(28376): Getting writable database for URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
01-14 08:40:46.698: DEBUG/GeckoBrowserProvider(28376): Insert on BOOKMARKS: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
01-14 08:40:46.698: DEBUG/GeckoBrowserProvider(28376): Extracting image values for URI: http://m.sesamestreet.org/
01-14 08:40:46.698: DEBUG/GeckoBrowserProvider(28376): Inserting bookmark in database with URL: http://m.sesamestreet.org/
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376): Store failed for SLaTXr7zXnd3
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376): android.database.sqlite.SQLiteConstraintException: error code 19: constraint failed
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at android.database.sqlite.SQLiteStatement.native_executeInsert(Native Method)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at android.database.sqlite.SQLiteStatement.executeInsert(SQLiteStatement.java:113)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at android.database.sqlite.SQLiteDatabase.insertWithOnConflict(SQLiteDatabase.java:1718)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at android.database.sqlite.SQLiteDatabase.insertOrThrow(SQLiteDatabase.java:1617)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at org.mozilla.fennec_rnewman.db.BrowserProvider.insertInTransaction(BrowserProvider.java:708)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at org.mozilla.fennec_rnewman.db.BrowserProvider.insert(BrowserProvider.java:658)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at android.content.ContentProvider$Transport.insert(ContentProvider.java:189)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at android.content.ContentResolver.insert(ContentResolver.java:729)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositoryDataAccessor.insert(AndroidBrowserRepositoryDataAccessor.java:106)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.insert(AndroidBrowserBookmarksRepositorySession.java:359)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession$1.run(AndroidBrowserRepositorySession.java:386)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1076)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
01-14 08:40:46.706: ERROR/AndroidBrowserRepositorySession(28376):     at java.lang.Thread.run(Thread.java:856)
01-14 08:40:46.706: DEBUG/ConcurrentRecordConsumer(28376): Record stored. Notifying.
01-14 08:40:46.706: INFO/System.out(28376): WARN: First RecordsChannel flow failed.
01-14 08:40:46.706: WARN/SynchronizerSession(28376): First RecordsChannel flow failed.
01-14 08:40:46.706: INFO/ServerSyncStage(28376): onSynchronizeAborted.
01-14 08:40:46.706: WARN/GlobalSession(28376): Aborting sync: Synchronization was aborted.
01-14 08:40:46.706: INFO/SyncAdapter(28376): GlobalSession indicated error. Flagging auth token as invalid, just in case.
01-14 08:40:46.706: INFO/SyncAdapter(28376): Notifying sync monitor.
01-14 08:40:46.706: INFO/ServerSyncStage(28376): onSynchronizeFailed: Got store error.
01-14 08:40:46.706: WARN/GlobalSession(28376): Aborting sync: Got store error.
01-14 08:40:46.706: WARN/GlobalSession(28376): android.database.sqlite.SQLiteConstraintException: error code 19: constraint failed
01-14 08:40:46.706: WARN/GlobalSession(28376):     at android.database.sqlite.SQLiteStatement.native_executeInsert(Native Method)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at android.database.sqlite.SQLiteStatement.executeInsert(SQLiteStatement.java:113)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at android.database.sqlite.SQLiteDatabase.insertWithOnConflict(SQLiteDatabase.java:1718)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at android.database.sqlite.SQLiteDatabase.insertOrThrow(SQLiteDatabase.java:1617)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at org.mozilla.fennec_rnewman.db.BrowserProvider.insertInTransaction(BrowserProvider.java:708)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at org.mozilla.fennec_rnewman.db.BrowserProvider.insert(BrowserProvider.java:658)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at android.content.ContentProvider$Transport.insert(ContentProvider.java:189)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at android.content.ContentResolver.insert(ContentResolver.java:729)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositoryDataAccessor.insert(AndroidBrowserRepositoryDataAccessor.java:106)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserBookmarksRepositorySession.insert(AndroidBrowserBookmarksRepositorySession.java:359)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at org.mozilla.gecko.sync.repositories.android.AndroidBrowserRepositorySession$1.run(AndroidBrowserRepositorySession.java:386)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1076)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
01-14 08:40:46.706: WARN/GlobalSession(28376):     at java.lang.Thread.run(Thread.java:856)
01-14 08:40:46.714: INFO/SyncAdapter(28376): GlobalSession indicated error. Flagging auth token as invalid, just in case.


Repro:
1) install rnewman's 1-14 0.2 drop of fennec sync
2) have initial sync working on device
3) launch accounts > firefox sync, and toggle the checkbox off and then on
4) verify when re-syncing, store error and NPE warnings are thrown

Expected:
- no errors

Comment 1

[Tony Chung [:tchung]]

also happens on initial sync with new account.  easy to reproduce.

Nightly Fennec, 1-17-2012, SGS2

Comment 3

[Richard Newman [:rnewman]]

Here's my theory.

* Create a bookmark in Fennec. It gets parent 1, the mobile folder (by accident).
* Pair with a Sync account that already has a mobile folder.
* First sync: the remote folder 'wins'.
* The Sync code at the time this bug occurred would replace a folder by deleting the original one and adding a new one.
* The new folder would have a different ID.
* Old bookmarks did not have a new parent ID assigned.
* In the upload phase, all old bookmarks that were in the Mobile Bookmarks folder will throw this error.

In essence, your browser database is now inconsistent, and there's no constraint in the database requiring a valid parent ID. (Filed Bug 723841.)

If this hypothesis is correct, my recent improvements to update bookmarks in-place will prevent this issue from happening again. However, we should ensure that operations on the database (such as folder deletions) preserve consistency.

Comment 4

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

Richard - did your improvements fix this?

Comment 5

[:Margaret Leibovic]

I don't think this is possible anymore after Lucas's patches from bug 723841.

Comment 6

[Richard Newman [:rnewman]]

Yup. Resolved by Bug 718238, probably four times over.

Fennec can't delete folders right now, so this should no longer be possible from either end.

Tracy can verify this when it hits m-c in the next inbound cutover.

Comment 7

[Tracy Walker [:tracy]]

Sure.  When would that be... tomorrow's m-c build?

Comment 8

[Richard Newman [:rnewman]]

(In reply to Tracy Walker [:tracy] from comment #7)
> Sure.  When would that be... tomorrow's m-c build?

m-i just got merged back with an earlier changeset, as far as I can tell. If another merge happens in the next 12 hours or so, it'll be in tomorrow's nightly (really "morningly"; build is early AM).

Comment 9

[Tracy Walker [:tracy]]

no longer seeing errors on m-c nightly