Firestore: deleted documents briefly reappear in cached snapshots

[aleh]

[REQUIRED] Step 2: Describe your environment

• Xcode version: 9.4 (9F1027a)
• Firebase SDK version: 5.4.1
• Firebase Component: Firestore
• Component version: 0.12.6

[REQUIRED] Step 3: Describe the problem

Steps to reproduce:

• Set up a query on any subcollection with a limit smaller than the number of elements in the subcollection already, for example, 5.

• Delete one of the first documents returned by the query.

• Observe that the query listener initially receives a snapshot without the deleted document, e.g. 4 documents in it for the query limited to last 5. Then it gets a cached snapshot with the original documents, so just deleted document appears as added back. Then comes a 3rd snapshot without the deleted document and with additional document in the end of the list pulled from the server.

• In case the result of the query is directly monitored by UI, then the UI flickers: the item is removed first, comes back again, and then is removed again.

• Note that our initial workaround where we ignored the cached snapshot in case we had some data already does not work in all the cases.

Logs from the example app:

2018-07-25 16:30:45.613118+0200 FirestoreSyncIssue[58674:20831755] Deleting the document for 'Stroopwafel #9'
2018-07-25 16:30:45.623390+0200 FirestoreSyncIssue[58674:20831755] Top 5 collection snapshot changed: 4 document(s) (from cache: 0)
2018-07-25 16:30:45.623700+0200 FirestoreSyncIssue[58674:20831755] Items: (
    "Coconut macaroon #10",
    "Oreo #7",
    "Charcoal biscuit #10",
    "Cream cracker #9"
)
2018-07-25 16:30:45.978800+0200 FirestoreSyncIssue[58674:20831755] Deleted 'Stroopwafel #9'
2018-07-25 16:30:46.343615+0200 FirestoreSyncIssue[58674:20831755] Top 5 collection snapshot changed: 5 document(s) (from cache: 1)
2018-07-25 16:30:46.343926+0200 FirestoreSyncIssue[58674:20831755] Items: (
    "Coconut macaroon #10",
    "Stroopwafel #9",
    "Oreo #7",
    "Charcoal biscuit #10",
    "Cream cracker #9"
)
2018-07-25 16:30:46.474503+0200 FirestoreSyncIssue[58674:20831755] Top 5 collection snapshot changed: 5 document(s) (from cache: 0)
2018-07-25 16:30:46.474843+0200 FirestoreSyncIssue[58674:20831755] Items: (
    "Coconut macaroon #10",
    "Oreo #7",
    "Charcoal biscuit #10",
    "Cream cracker #9",
    "Charcoal biscuit #8"
)

Relevant Code:

See the example app and another video.

[mikelehen]

This is likely a dupe of #1045 and tracked internally by b/33446471.

[aleh]

@mikelehen Yes, we've been told that this was something known when were reporting this via the Firebase support channel. We thought that a workaround ignoring cached snapshots would fix this for us so we ignored this issue for a while.

Recently we've discovered that in some cases the workaround makes things worse because then we can miss actual document deletes sometimes and then the app can be trying to fetch a non-existing document or update a single field of it thinking it's there further confusing the things. So we decided to file the issue here with a code example.

Also, it seems like there is no progress on this despite it being very obvious flaw that is easy to reproduce, so filing a dupe should not hurt :)

[mikelehen]

Thanks @aleh! Yeah, I have no complaint with you filing a dupe, and sorry progress has been slow here. The fix involves a large refactor and potentially storing additional data in our persistence cache (which means schema changes which are painful to make). But you're right that this is an obvious flaw when you hit it (it mostly comes up with limit queries + deletes) and we appreciate the extra feedback. :-)

If you're interested in discussing your workaround pitfalls, feel free to ping me (michael@firebase.com). I was thinking that if you use the includeMetadataChanges option on your listener and just ignore fromCache updates, that should work. But I may be mistaken.

[aleh]

@mikelehen All our queries on subcollections are limited and I believe that's the normal use case in production apps. I guess I need to demo the case when ignoring the cached data is not working.

[mikelehen]

@aleh Hey, I'm really sorry but it turns out I was wrong. The underlying issue here is not what I originally thought. After debugging through this it turns out there's a relatively simple cause for your symptom and I've put together a fix in #1622. I've tested with your repro (thanks very much for providing it!) and the flickering issue seems to be resolved.

[aleh]

@mikelehen Thanks a lot! That's just in time before our release. We'll test it.

By the way, I have not got around to demo problems with "ignore cache" workaround in online mode, but have seen it in offline mode: just remove a couple of items and then notice that ignored cached snapshots won't allow to update your UI.

[aleh]

@mikelehen It seems to be working however I have a backend connectivity issue when using the recent library:

2018-08-02 12:09:19.264435+0200 FirestoreSyncIssue[73826:1670580] 5.4.1 - [Firebase/Firestore][I-FST000001] Could not reach Cloud Firestore backend. Backend didn't respond within 10.000000 seconds.
 This typically indicates that your device does not have a healthy Internet connection at the moment. The client will operate in offline mode until it is able to successfully connect to the backend.

If I switch back to the official release, then it connects without any problems, switching again and it fails all the time.

My Podfile:

target 'FirestoreSyncIssue' do
	pod 'FirebaseCore', :git => "https://github.com/firebase/firebase-ios-sdk.git", :branch => "master"
	pod 'FirebaseFirestore', :git => "https://github.com/firebase/firebase-ios-sdk.git" , :branch => "master"
	pod 'FirebaseAuthInterop', :git => "https://github.com/firebase/firebase-ios-sdk.git", :branch => "master"
end

[mikelehen]

I ran into that too. It happens with or without my fix when you build against the current bits from master. I haven't dug into it yet so I'm not sure if there's an actual bug in master or if there are just changes in master that prevent picking out components in your Podfile like that right now.

For now, I just threw up a branch that's synced to the latest release + cherry-picking my fix. So you can give that a try with something like:

pod 'Firebase/Core'
pod 'FirebaseFirestore', :git => "https://github.com/firebase/firebase-ios-sdk.git" , :branch => "mikelehen/test-delete-fix"

Can you give that a try?

[aleh]

@mikelehen Your branch is working properly. Thanks!

[wilhuff]

The fix for this issue was released as part of Firebase 5.5.0.

[aleh]

@wilhuff Great, can confirm it works as well. Thanks a lot!

[jhoughjr]

I don't know if this is fixed. I'm using firebase 6.0 iOS. deleted a collection 30 mins ago, it's not in console. somehow I'm still getting query results from a non existent collection.
I'm really really regretting my client's decision to use firebase.

[wilhuff]

@jhoughjr The issues discussed here had very specific known causes and fixes. The symptoms were specifically that deleted documents would very briefly reappear--they would flicker. What you're describing is very different.

Could you open a new issue, showing what you're doing? If the issue is persisting also supply logs after enabling debug logging?