Closed Bug 1153973 Opened 8 years ago Closed 8 years ago

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

Categories

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

Product:
Android Background Services Graveyard
Component:
Reading List Sync
Platform:
All
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

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

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

People

(Reporter: nalexander, Assigned: rnewman)

Details

Attachments

(2 files)

Pre: add logging for DB insert failures. v1
3.41 KB, patch
nalexander
: review+
Details | Diff | Splinter Review
Don't apply deletions as insertions.
96 bytes, patch
nalexander
: review+
Sylvestre
: approval-mozilla-aurora+
Sylvestre
: approval-mozilla-beta+
Details | Diff | Splinter Review 
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+
status-firefox38: --- → ?
status-firefox39: --- → ?
status-firefox40: --- → affected

        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: 8 years ago

          status-firefox40:
          affected → fixed
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: 8 years ago → 8 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.