Query snapshots not updating after returning to foreground

[bswhite1]

Describe your environment

• Android Studio version: Artic Fox 2020.3.1 Patch 4
• Firebase Component: Firestore
• Component version: Firebase BoM 29.0.0, firestore: 24.0.0. Master as of commit: d0048fd

Describe the problem

Issue first documented here: firebase/flutterfire#7323

Updated problem description:
When the app returns to the foreground after being in the background for several hours, the listeners for QuerySnapshots can return wrong data. It only returns updates to the collection that were made while the app was in the background, or new updates after it is returned to the foreground. Unchanged documents are not returned. A force close and restart of the app corrects the issue.

Current debug analysis:

As mentioned above, issue was seen in Firebase BoM 29.0.0, firestore: 24.0.0
Issue is still seen in master as of this commit: d0048fd

I have tracked the issue down to this series of events.

Starting with the log where the app is the background.
App is started up and logs look good.
App is sent to the background and appears to go to sleep.
Eventually it may wake up and log something like this

• [WatchStream]: (b390c6) Stream sending: # com.google.firestore.v1.ListenRequest
  • target_id matches target_id of query experiencing issue.
  • labels { value: "existence-filter-mismatch"}
• RemoteStore.raiseWatchSnapshot (snapshotVersion)
• Creates remoteEvent from watchChangeAggregator.createRemoteEvent(snapshotVersion)
  • Parses through remoteEvent.getTargetMismatches()
    • targetID of problem query is present.
    • this.sendUnwatchRequest(targetId)
    • this.sendWatchRequest(requestTargetData)
  • remoteStoreCallback.handleRemoteEvent(remoteEvent);
    • SyncEngine.handleRemoteEvent (event)
      • LocalStore.applyRemoteEvent (remoteEvent)
        • targetCache.removeMatchingKeys(change.getRemovedDocuments(), targetId);
          • SQLiteTargetCache.removeMatchingKeys // This removes the documents tied to the targetId in the targetCache.
      • emitNewSnapsAndNotifyLocalStore(changes, event)
      • listen snapshot appears to still have all of the documents for query.

I do not get any other events or data past this point. Phone appears to go back to sleep

When the phone is turned on and app is brought back to foreground, the app gets restarted and this is what I log.

• SyncEngine.listen (query)
  • SyncEngine.initializeViewAndComputeSnapshot
    • queryResult = localStore.executeQuery
      • remoteKeys = this.targetCache.getMatchingKeysForTargetId(targetData.getTargetId())
        • Target cache is empty since we deleted it above.
      • DefaultQueryEngine.getDocumentsMatchingQuery
        • Since targetCache is empty, we return 0 documents.
        • Note. If I force executeFullCollectionScan(query) it appears to fix the issue. however this is not usually called since lastLimboFreeSnapshotVersion != none and I don't have a limit on the query
    • Initial snapshot has 0 documents.
    • Note: this would be "fromCache = true"

After some time, I receive the listener from the server.

• raiseWatchSnapshot Calling handleRemoteEvent.
  • applyRemoteEvent
    • SQLiteTargetCache addMatchingKeys
      • document added to targetID // Repopulates target cache
    • populateDocumentChanges
      • [LocalStore]: Ignoring outdated watch update since current version == watch version
  • snapshot still has 0 documents. note: this would be "fromCache = false"

If we reboot the app again. target cache has been repopulated, so initial snapshot has correct documents.

Questions:

Looking for some help to either point me in the direction of a fix, or places to add more debugging. This is the first time I have dug into this code, so an unfamiliar with it, and what the purpose of things are. My initial thought is to set lastLimboFreeSnapshotVersion to none but that seems to be read/set multiple places. Also not sure if that is the correct fix.

[itaishalom]

I found out that if you disable the cache:

.get(GetOptions(source: Source.server));

You will get an exception -

[cloud_firestore/unavailable] The service is currently unavailable. This is a most likely a transient condition and may be corrected by retrying with a backoff.
#0 MethodChannelQuery.get (package:cloud_firestore_platform_interface/src/method_channel/method_channel_query.dart:110:7)

#1 _JsonQuery.get (package:cloud_firestore/src/query.dart:390:9)

#2 FirebaseChatCore.getInitialMessages (package:AIDOC/chat/services/firebase_core.dart:124:16)

But the internet is available and it happens only when coming back from foreground,

[argzdev]

Hi @bswhite1, thanks for filing. We'll try to investigate this and see what we can find. In the meantime, if you could provide us a MCVE of the issue with debug logging enabled and attach the resulting logs, that'll greatly help us in our investigation. Thanks!

[itaishalom]

@bswhite1 Can you please try to call (on firestore failed):
await FirebaseFirestore.instance.terminate();
and again:
FirebaseFirestore.instance.settings = Settings( persistenceEnabled: false, );
And now do the query/get again?
I think it solved my problem.

[bswhite1]

@itaishalom I don't believe your issue is related to my issue. I am not getting failures or exceptions on connecting to firestore.
My issue is the query results from cache when returning from background are incorrect. I listed in my flutterfire issue that it works properly when cache is disabled. This was only a debugging step and not a solution.

[bswhite1]

@argzdev Unfortunately I do not have an example program that exhibits the behavior. I tried making one for a while, but was unsuccessful. Only seems to be easily reproducible in our production app. Currently running a test with some edits in the localStore and targetCache.

[argzdev]

Hi @bswhite1, thanks for the extra details. It is plausible that this could be an underlying issue with the native SDK, however given that we aren't able to test this with a minimal reproducible example with native android. It's hard to say where the issue lies. We'll keep this open while we investigate this further.

[schmidt-sebastian]

@bswhite1 Thanks for for all these details. Can you answer some questions that will help determine if this is an SDK issue?

• Do you have logs that show the backend communication? You can send them to mrschmidt(at)google.com if they contain sensitive information.
• I assume you are using persistence. Please let us know if you are not.
• Do you know if the step SQLiteTargetCache.removeMatchingKeys // This removes the documents tied to the targetId in the targetCache. removes all keys for the target? Or does it just remove keys for documents that were actually deleted?

As I see it now, your cache seems to be going out of sync and not all data is correctly persisted.

[schmidt-sebastian]

Thank you for sending the data over email. I suspect that the local query state goes out of sync because we clear the internal mapping for the query but not the resume information. Usually, this is not a problem as we restart the query right away, which then fixes our internal state. This does not happen here because the app is backgrounded.

I think this PR fixes this issue: #3267

If you have time, it would be wonderful if you could verify this.

[bswhite1]

Thanks. I will try it out as is from your PR. However, I wonder if we need to add .withLastLimboFreeSnapshotVersion(SnapshotVersion.NONE); to the newTargetData
When I added that to my fork, it fixed the issue. I'll let you know either way.

[schmidt-sebastian]

I suspect that you are right. I will update the PR.