Firestore fails to read large write batches

[brucemax]

[REQUIRED] Step 2: My environment

• Android Studio version: 3.3
• Firebase Component: Firestore
• Component version: 17.1.5

[REQUIRED] Step 3: Describe the problem

Some my app user get this crash during batch.commit() (HUAWEI VTR-L09 Android 8.0.0)

Fatal Exception: java.lang.RuntimeException: Internal error in Firestore (0.6.6-dev).
at com.google.firebase.firestore.util.AsyncQueue.lambda$panic$5(com.google.firebase:firebase-firestore@@17.1.5:377)
at com.google.firebase.firestore.util.AsyncQueue$$Lambda$5.run(Unknown Source:2)
at android.os.Handler.handleCallback(Handler.java:808)
at android.os.Handler.dispatchMessage(Handler.java:101)
at android.os.Looper.loop(Looper.java:166)
at android.app.ActivityThread.main(ActivityThread.java:7523)
at java.lang.reflect.Method.invoke(Method.java)
at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:245)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:921)

Caused by java.lang.RuntimeException: java.lang.IllegalStateException: Couldn't read row 0, col 0 from CursorWindow. Make sure the Cursor is initialized correctly before accessing data from it.
at com.google.firebase.firestore.util.AsyncQueue.enqueue(com.google.firebase:firebase-firestore@@17.1.5:288)
at com.google.firebase.firestore.util.AsyncQueue$$Lambda$3.run(Unknown Source:4)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:457)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
at com.google.firebase.firestore.util.AsyncQueue$DelayedStartFactory.run(com.google.firebase:firebase-firestore@@17.1.5:203)
at java.lang.Thread.run(Thread.java:784)

Caused by java.lang.IllegalStateException: Couldn't read row 0, col 0 from CursorWindow. Make sure the Cursor is initialized correctly before accessing data from it.
at android.database.CursorWindow.nativeGetBlob(CursorWindow.java)
at android.database.CursorWindow.getBlob(CursorWindow.java:405)
at android.database.AbstractWindowedCursor.getBlob(AbstractWindowedCursor.java:45)
at com.google.firebase.firestore.local.SQLiteMutationQueue.lambda$getNextMutationBatchAfterBatchId$4(com.google.firebase:firebase-firestore@@17.1.5:248)
at com.google.firebase.firestore.local.SQLiteMutationQueue$$Lambda$5.apply(Unknown Source:4)
at com.google.firebase.firestore.local.SQLitePersistence$Query.firstValue(com.google.firebase:firebase-firestore@@17.1.5:442)
at com.google.firebase.firestore.local.SQLiteMutationQueue.getNextMutationBatchAfterBatchId(com.google.firebase:firebase-firestore@@17.1.5:248)
at com.google.firebase.firestore.local.LocalStore.getNextMutationBatch(com.google.firebase:firebase-firestore@@17.1.5:451)
at com.google.firebase.firestore.remote.RemoteStore.fillWritePipeline(com.google.firebase:firebase-firestore@@17.1.5:539)
at com.google.firebase.firestore.remote.RemoteStore.enableNetwork(com.google.firebase:firebase-firestore@@17.1.5:221)
at com.google.firebase.firestore.remote.RemoteStore.start(com.google.firebase:firebase-firestore@@17.1.5:252)
at com.google.firebase.firestore.core.FirestoreClient.initialize(com.google.firebase:firebase-firestore@@17.1.5:225)
at com.google.firebase.firestore.core.FirestoreClient.lambda$new$2(com.google.firebase:firebase-firestore@@17.1.5:108)
at com.google.firebase.firestore.core.FirestoreClient$$Lambda$2.run(Unknown Source:8)
at com.google.firebase.firestore.util.AsyncQueue.lambda$enqueue$4(com.google.firebase:firebase-firestore@@17.1.5:309)
at com.google.firebase.firestore.util.AsyncQueue$$Lambda$4.call(Unknown Source:2)
at com.google.firebase.firestore.util.AsyncQueue.enqueue(com.google.firebase:firebase-firestore@@17.1.5:285)
at com.google.firebase.firestore.util.AsyncQueue$$Lambda$3.run(Unknown Source:4)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:457)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
at com.google.firebase.firestore.util.AsyncQueue$DelayedStartFactory.run(com.google.firebase:firebase-firestore@@17.1.5:203)
at java.lang.Thread.run(Thread.java:784)

Relevant Code:

Init Firestore

FirebaseFirestore db = FirebaseFirestore.getInstance();
            FirebaseFirestoreSettings settings = new FirebaseFirestoreSettings.Builder()
                    .setTimestampsInSnapshotsEnabled(true)
                    .build();
            db.setFirestoreSettings(settings);

if (realmTablesResult.size() > 0) {
            WriteBatch batch = db.batch();
            Gson gson = new Gson();
            List<HistoryTrainingTable> arrayListOfUnmanagedObjects = realm.copyFromRealm(realmTablesResult);
            for (HistoryTrainingTable historyTrainingTable : arrayListOfUnmanagedObjects) {
                FATrainingTableHistory historyItem = new FATrainingTableHistory();
                historyItem.id = historyTrainingTable.getId();
                historyItem.trainingDate = historyTrainingTable.getTrainingDate();
                historyItem.description = gson.toJson(historyTrainingTable);
                historyItem.bestTimeValue = historyTrainingTable.getBestTimeValue();
                historyItem.avgContractionTime = historyTrainingTable.getAvgContractionTime();

                DocumentReference nycRef = db.collection("history/" + userId + "/userHistory/").document(String.valueOf(historyTrainingTable.getId()));
                batch.set(nycRef, historyItem);
            }


            // Commit the batch
            batch.commit().addOnCompleteListener(new OnCompleteListener<Void>() {
                @Override
                public void onComplete(@NonNull Task<Void> task) {
                    Log.d("myTag", "batch.commit() complete");
                }
            });
        }

        db.collection("history/"+userId+"/userHistory/")
                .get()

public class FATrainingTableHistory {

    public String id;
    public String description;
    public int bestTimeValue;
    public Date trainingDate;
    public int avgContractionTime;
}

[wilhuff]

Do you think it's possible that you're storing very large data in the batch? The only time I've seen this kind of error is if the blob data is too large for SQLite to initialize.

[wilhuff]

I've managed to reproduce this by writing a large batch (2 MB).

Firestore is supposed to handle batches of up to 500 changes where each change could be a document of up to 1 MB. Write batches are serialized into SQLite as blobs and clearly SQLite's default limit of 2 MB on reading a blob that doesn't apply when writing a blob is not helpful.

In the short term, my advice is to avoid creating batches that large. In the longer term we need to be able to read existing large values and handle values much larger than a single batch. I'm not yet sure what the approach should be here, but we need to fix this.

[brucemax]

Thanks for your answer.

Do you think it's possible that you're storing very large data in the batch? The only time I've seen this kind of error is if the blob data is too large for SQLite to initialize.

Yeah, as you see in code I try to sync user history in this place.

In the short term, my advice is to avoid creating batches that large.

So how I could control batch size in this case? In other words what better way to store such big number of documents?

[wilhuff]

Does the history really need to be committed atomically? Write batches aren’t so much a performance optimization as a mechanism for performing writes atomically. Splitting these into individual sets outside a batch would be a start.

[wilhuff]

The change in #215 should fix this, but unfortunately it just missed the release train that boarded last week. This will be released with our next patch release.

[brucemax]

@wilhuff Thanks for help!

One more. Also after I start get this message on batch() for some reason the same appear when I try set small object:

db.document("history/" + userId + "/userHistory/" + historyTrainingTable.getId())
                .set(historyItem) 

{"avgContractionTime":0,"bestTimeValue":0,"description":"{"avgContractionTime":0,"bestTimeValue":0,"description":"Increases our ability to withstand lower levels of O2","id":"a61912c8-a1de-4369-b69f-6905902b9959","isTableForSaving":false,"name":"O2-table","rounds":[{"contractionTime":0,"extraRestTime":0,"extraRoundTime":0,"id":0,"isActive":false,"isLastRound":false,"restTime":30,"roundNumber":1,"roundTime":30},{"contractionTime":0,"extraRestTime":0,"extraRoundTime":0,"id":0,"isActive":false,"isLastRound":false,"restTime":30,"roundNumber":2,"roundTime":40},{"contractionTime":0,"extraRestTime":0,"extraRoundTime":0,"id":0,"isActive":false,"isLastRound":false,"restTime":30,"roundNumber":3,"roundTime":10}],"trainingDate":"Jan 29, 2019 17:12:55"}","id":"a61912c8-a1de-4369-b69f-6905902b9959","trainingDate":{"nanoseconds":887000000,"seconds":1548771175}}

java.lang.RuntimeException: Internal error in Firestore (0.6.6-dev).
at com.google.firebase.firestore.util.AsyncQueue.lambda$panic$5(com.google.firebase:firebase-firestore@@17.1.5:377)
at com.google.firebase.firestore.util.AsyncQueue$$Lambda$5.run(Unknown Source:2)
at android.os.Handler.handleCallback(Handler.java:873)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loop(Looper.java:193)
at android.app.ActivityThread.main(ActivityThread.java:6762)
at java.lang.reflect.Method.invoke(Native Method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)
Caused by: java.lang.RuntimeException: android.database.sqlite.SQLiteBlobTooBigException: Row too big to fit into CursorWindow requiredPos=0, totalRows=1
at com.google.firebase.firestore.util.AsyncQueue.lambda$enqueue$3(com.google.firebase:firebase-firestore@@17.1.5:288)
at com.google.firebase.firestore.util.AsyncQueue$$Lambda$3.run(Unknown Source:4)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:458)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at com.google.firebase.firestore.util.AsyncQueue$DelayedStartFactory.run(com.google.firebase:firebase-firestore@@17.1.5:203)
at java.lang.Thread.run(Thread.java:764)
Caused by: android.database.sqlite.SQLiteBlobTooBigException: Row too big to fit into CursorWindow requiredPos=0, totalRows=1
at android.database.sqlite.SQLiteConnection.nativeExecuteForCursorWindow(Native Method)
at android.database.sqlite.SQLiteConnection.executeForCursorWindow(SQLiteConnection.java:859)
at android.database.sqlite.SQLiteSession.executeForCursorWindow(SQLiteSession.java:836)
at android.database.sqlite.SQLiteQuery.fillWindow(SQLiteQuery.java:62)
at android.database.sqlite.SQLiteCursor.fillWindow(SQLiteCursor.java:149)
at android.database.sqlite.SQLiteCursor.getCount(SQLiteCursor.java:137)
at android.database.AbstractCursor.moveToPosition(AbstractCursor.java:220)
at android.database.AbstractCursor.moveToFirst(AbstractCursor.java:259)
at com.google.firebase.firestore.local.SQLitePersistence$Query.firstValue(com.google.firebase:firebase-firestore@@17.1.5:441)
at com.google.firebase.firestore.local.SQLiteMutationQueue.getNextMutationBatchAfterBatchId(com.google.firebase:firebase-firestore@@17.1.5:248)
at com.google.firebase.firestore.local.LocalStore.getNextMutationBatch(com.google.firebase:firebase-firestore@@17.1.5:451)
at com.google.firebase.firestore.remote.RemoteStore.fillWritePipeline(com.google.firebase:firebase-firestore@@17.1.5:539)
at com.google.firebase.firestore.remote.RemoteStore.enableNetwork(com.google.firebase:firebase-firestore@@17.1.5:221)
at com.google.firebase.firestore.remote.RemoteStore.start(com.google.firebase:firebase-firestore@@17.1.5:252)
at com.google.firebase.firestore.core.FirestoreClient.initialize(com.google.firebase:firebase-firestore@@17.1.5:225)
at com.google.firebase.firestore.core.FirestoreClient.lambda$new$2(com.google.firebase:firebase-firestore@@17.1.5:108)
at com.google.firebase.firestore.core.FirestoreClient$$Lambda$2.run(Unknown Source:8)
at com.google.firebase.firestore.util.AsyncQueue.lambda$enqueue$4(com.google.firebase:firebase-firestore@@17.1.5:309)
at com.google.firebase.firestore.util.AsyncQueue$$Lambda$4.call(Unknown Source:2)
at com.google.firebase.firestore.util.AsyncQueue.lambda$enqueue$3(com.google.firebase:firebase-firestore@@17.1.5:285)
at com.google.firebase.firestore.util.AsyncQueue$$Lambda$3.run(Unknown Source:4) 
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:458) 
at java.util.concurrent.FutureTask.run(FutureTask.java:266) 
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301) 
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) 
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) 
at com.google.firebase.firestore.util.AsyncQueue$DelayedStartFactory.run(com.google.firebase:firebase-firestore@@17.1.5:203) 
at java.lang.Thread.run(Thread.java:764) 

Any ideas how I could change code for fix that? May be I could somehow get snapshot version with mentioned fix for test?

Upd:
I noticed that delete method also get the same result, looks like firestore keep last wrong batch result (but in this case I don't use batch or transaction methods). So user stuck in this case and can't either remove data for reducing sync data size. Seems it's not just about batch method

[brucemax]

Firestore methods (set, delete) fails until user delete app data from app phone settings. So for fix user need clear app data and login again, but in this case he lose unsaved data (because set method always fails after first batch crash). May be there is a method for reset "batch memory" and user no need to remove all app data?
Also as I see possible global solution for me it is remove sync ability. Or is it make sense to move 100+ set methods (in for operator) to background thread?

[wilhuff]

Yes, unfortunately, the current version of the Firestore SDK can write these very large blobs but cannot read them back. All writes are queued locally, and these large blobs are stuck at the head of the queue: it can't read them to send them to the server. This means that regardless of what you do after writing a large blob like this you're stuck. The subsequent failures you're seeing don't mean that set and delete aren't working, just that the queue is stuck.

If your application can tolerate dropping these queued writes then you can delete the database file before starting Firestore to clear these local writes.

Otherwise the change in #215 will be able to read the large blobs at the head of the queue and will be able clear the queue for your end users.

You can build a local copy of the SDK sources using the instructions in the readme. Let us know if you run into any difficulty doing so.

[brucemax]

Morning!
I build snapshot version from master branch and tested it.
"set" and "delete" methods not crash app now, thanks! but first "set" method take a long time (about 10-15 until complete method called, not big problem just notice). I suppose that time was spent for clear queue. Next "set" calls take time like usual.

Also could you suggest approach for waiting when "Splitting individual sets" complete. How I could determinate complete event when call "set" method in loop for avoid using "batch" (as you suggested above)

[wilhuff]

"set" and "delete" methods not crash app now, thanks!

Glad to hear it worked for you!

but first "set" method take a long time (about 10-15 until complete method called, not big problem just notice). I suppose that time was spent for clear queue. Next "set" calls take time like usual.

Correct, writes are resolved in order and any accumulated writes must be processed before any newly submitted ones.

Also could you suggest approach for waiting when "Splitting individual sets" complete. How I could determinate complete event when call "set" method in loop for avoid using "batch" (as you suggested above)

In the Firestore mobile clients, each write implicitly depends upon all writes that precede it. If you want to wait for all the sets in a loop to complete, just wait for the last one.

I'm going to close this issue for now just to properly reflect that the fix has been submitted and is scheduled for the next release. Feel free to follow up with additional questions after that.