Closed Bug 1153973 Opened 6 years ago Closed 6 years ago

android.content.OperationApplicationException: insert failed during Reading List sync

Categories

(Android Background Services Graveyard :: Reading List Sync, defect)

All
Android
defect
Not set
normal

Tracking

(firefox38 fixed, firefox39 fixed, firefox40 fixed, fennec38+)

RESOLVED FIXED
Firefox 40
Tracking Status
firefox38 --- fixed
firefox39 --- fixed
firefox40 --- fixed
fennec 38+ ---

People

(Reporter: nalexander, Assigned: rnewman)

Details

Attachments

(2 files)

Reported by sphilp.  He's seeing intermittent insert errors with stack traces like:

I/FxReadingList(13182): fennec :: ReadingListSyncAdapter :: Syncing reading list against endpoint: https://readinglist.services.mozilla.com/v1/
I/FxReadingList(13182): fennec :: ReadingListSynchronizer :: Server last modified: 1428941903537
W/FxReadingList(13182): fennec :: RLChanges :: Applying operations failed.
W/FxReadingList(13182): android.content.OperationApplicationException: insert failed
W/FxReadingList(13182): at android.content.ContentProviderOperation.apply(ContentProviderOperation.java:246)
W/FxReadingList(13182): at android.content.ContentProvider.applyBatch(ContentProvider.java:1733)
W/FxReadingList(13182): at android.content.ContentProvider$Transport.applyBatch(ContentProvider.java:297)
W/FxReadingList(13182): at android.content.ContentProviderClient.applyBatch(ContentProviderClient.java:377)
W/FxReadingList(13182): at org.mozilla.gecko.reading.LocalReadingListStorage$LocalReadingListChangeAccumulator.flushRecordChanges(LocalReadingListStorage.java:135)
W/FxReadingList(13182): at org.mozilla.gecko.reading.LocalReadingListStorage$LocalReadingListChangeAccumulator.finish(LocalReadingListStorage.java:212)
W/FxReadingList(13182): at org.mozilla.gecko.reading.ReadingListSynchronizer$3.onComplete(ReadingListSynchronizer.java:789)
W/FxReadingList(13182): at org.mozilla.gecko.reading.ReadingListClient$MultipleRecordResourceDelegate.onSuccess(ReadingListClient.java:268)
W/FxReadingList(13182): at org.mozilla.gecko.reading.ReadingListClient$ReadingListResourceDelegate.handleHttpResponse(ReadingListClient.java:126)
W/FxReadingList(13182): at org.mozilla.gecko.sync.net.BaseResource.execute(BaseResource.java:306)
W/FxReadingList(13182): at org.mozilla.gecko.sync.net.BaseResource.go(BaseResource.java:337)
W/FxReadingList(13182): at org.mozilla.gecko.sync.net.BaseResource.get(BaseResource.java:343)
W/FxReadingList(13182): at org.mozilla.gecko.reading.ReadingListClient.getAll(ReadingListClient.java:521)
W/FxReadingList(13182): at org.mozilla.gecko.reading.ReadingListSynchronizer.access$000(ReadingListSynchronizer.java:32)
W/FxReadingList(13182): at org.mozilla.gecko.reading.ReadingListSynchronizer$9.doNext(ReadingListSynchronizer.java:949)
W/FxReadingList(13182): at org.mozilla.gecko.reading.ReadingListSynchronizer$NextDelegate$1.run(ReadingListSynchronizer.java:62)
W/FxReadingList(13182): at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
W/FxReadingList(13182): at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
W/FxReadingList(13182): at java.lang.Thread.run(Thread.java:818)
I/FxReadingList(13182): fennec :: ReadingListSyncAdapter :: Reading list synchronization complete.
Let's add some logging.
Assignee: nobody → rnewman
Status: NEW → ASSIGNED
tracking-fennec: --- → 38+
Attachment #8591829 - Flags: review?(nalexander)
Comment on attachment 8591829 [details] [diff] [review]
Pre: add logging for DB insert failures. v1

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

Sure.
Attachment #8591829 - Flags: review?(nalexander) → review+
ni on sphilp to grab new logs when this reaches Nightly (should be Tuesday morning's, I hope).
Flags: needinfo?(sphilp)
Thanks, I'll check in the morning. GeckoRLProvider is what I should filter for logcat, right?
Flags: needinfo?(sphilp)
https://hg.mozilla.org/mozilla-central/rev/bc1d767b3e0c
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 40
Here's the SQL error, this came after removing an item (not sure if that's the only way to trigger it yet)

D/SharedBrowserDatabaseProvider(11468): Cleaning up deleted records from reading_list

followed by 

E/SQLiteLog(11468): (1299) abort at 23 in [INSERT INTO reading_list(sync_change_flags,client_last_modified,last_modified,is_deleted,guid,sync_status) VALUES (?,?,?,?,?,?)]: NOT NULL constraint failed: reading_list.url
E/GeckoTransProvider(11468): exception in DB operation
E/GeckoTransProvider(11468): android.database.sqlite.SQLiteConstraintException: NOT NULL constraint failed: reading_list.url (code 1299)
E/GeckoTransProvider(11468): 	at android.database.sqlite.SQLiteConnection.nativeExecuteForLastInsertedRowId(Native Method)
E/GeckoTransProvider(11468): 	at android.database.sqlite.SQLiteConnection.executeForLastInsertedRowId(SQLiteConnection.java:812)
E/GeckoTransProvider(11468): 	at android.database.sqlite.SQLiteSession.executeForLastInsertedRowId(SQLiteSession.java:788)
E/GeckoTransProvider(11468): 	at android.database.sqlite.SQLiteStatement.executeInsert(SQLiteStatement.java:86)
E/GeckoTransProvider(11468): 	at android.database.sqlite.SQLiteDatabase.insertWithOnConflict(SQLiteDatabase.java:1549)
E/GeckoTransProvider(11468): 	at android.database.sqlite.SQLiteDatabase.insertOrThrow(SQLiteDatabase.java:1439)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.db.ReadingListProvider.insertItem(ReadingListProvider.java:160)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.db.ReadingListProvider.insertInTransaction(ReadingListProvider.java:317)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.db.AbstractTransactionalProvider.insert(AbstractTransactionalProvider.java:210)
E/GeckoTransProvider(11468): 	at android.content.ContentProviderOperation.apply(ContentProviderOperation.java:244)
E/GeckoTransProvider(11468): 	at android.content.ContentProvider.applyBatch(ContentProvider.java:1733)
E/GeckoTransProvider(11468): 	at android.content.ContentProvider$Transport.applyBatch(ContentProvider.java:297)
E/GeckoTransProvider(11468): 	at android.content.ContentProviderClient.applyBatch(ContentProviderClient.java:377)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.reading.LocalReadingListStorage$LocalReadingListChangeAccumulator.flushRecordChanges(LocalReadingListStorage.java:135)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.reading.LocalReadingListStorage$LocalReadingListChangeAccumulator.finish(LocalReadingListStorage.java:212)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.reading.ReadingListSynchronizer$3.onComplete(ReadingListSynchronizer.java:789)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.reading.ReadingListClient$MultipleRecordResourceDelegate.onSuccess(ReadingListClient.java:268)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.reading.ReadingListClient$ReadingListResourceDelegate.handleHttpResponse(ReadingListClient.java:126)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.sync.net.BaseResource.execute(BaseResource.java:306)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.sync.net.BaseResource.go(BaseResource.java:337)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.sync.net.BaseResource.get(BaseResource.java:343)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.reading.ReadingListClient.getAll(ReadingListClient.java:521)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.reading.ReadingListSynchronizer.access$000(ReadingListSynchronizer.java:32)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.reading.ReadingListSynchronizer$9.doNext(ReadingListSynchronizer.java:949)
E/GeckoTransProvider(11468): 	at org.mozilla.gecko.reading.ReadingListSynchronizer$NextDelegate$1.run(ReadingListSynchronizer.java:62)
E/GeckoTransProvider(11468): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
E/GeckoTransProvider(11468): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
E/GeckoTransProvider(11468): 	at java.lang.Thread.run(Thread.java:818)
Status: RESOLVED → REOPENED
Flags: needinfo?(rnewman)
Flags: needinfo?(nalexander)
Resolution: FIXED → ---
I think this might happen if you manage to both add and delete an item on another device before Android is able to sync. We'll download the ultimate record state, which is "this GUID was deleted"; we'll try to apply the change, find that the GUID doesn't exist locally, and end up trying to insert. The insertion will fail with this error because there's no URL in a deleted record payload.

The change accumulator needs to be smarter in addDownloadedRecord.
Status: REOPENED → ASSIGNED
Flags: needinfo?(rnewman)
Flags: needinfo?(nalexander)
No longer blocks: desktop-readinglist
New test passes.
Attachment #8592434 - Flags: review?(nalexander)
Comment on attachment 8592434 [details] [diff] [review]
Don't apply deletions as insertions.

lgtm.
Attachment #8592434 - Flags: review?(nalexander) → review+
https://hg.mozilla.org/mozilla-central/rev/026db6918fdf
Status: ASSIGNED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → FIXED
Comment on attachment 8592434 [details] [diff] [review]
Don't apply deletions as insertions.

Approval Request Comment
[Feature/regressing bug #]:
  Initial landing of RL.

[User impact if declined]:
  Records deleted elsewhere won't be handled correctly.

[Describe test coverage new/current, TreeHerder]:
  New test added.

[Risks and why]: 
  Pretty low risk.

[String/UUID change made/needed]:
  None.
Attachment #8592434 - Flags: approval-mozilla-beta?
Attachment #8592434 - Flags: approval-mozilla-aurora?
Comment on attachment 8592434 [details] [diff] [review]
Don't apply deletions as insertions.

Should be in 38 beta 6
Attachment #8592434 - Flags: approval-mozilla-beta?
Attachment #8592434 - Flags: approval-mozilla-beta+
Attachment #8592434 - Flags: approval-mozilla-aurora?
Attachment #8592434 - Flags: approval-mozilla-aurora+
Looks good on nightly!
You need to log in before you can comment on or make changes to this bug.