Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Firestore: deleted documents briefly reappear in cached snapshots #1591

Closed
aleh opened this issue Jul 26, 2018 · 13 comments · Fixed by #1622

Comments

@aleh
Copy link

commented Jul 26, 2018

[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 comment has been minimized.

Copy link
Member

commented Jul 26, 2018

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

@aleh

This comment has been minimized.

Copy link
Author

commented Jul 26, 2018

@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

This comment has been minimized.

Copy link
Member

commented Jul 26, 2018

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

This comment has been minimized.

Copy link
Author

commented Jul 27, 2018

@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 added a commit that referenced this issue Aug 2, 2018
Fixes decoding WriteResults for deletes (with no updateTime).
This should resolve #1591.  We were inadvertantly decoding the WriteResult as
having an updateTime of 0 which caused it to be older than the version of the
document in the RemoteDocumentsCache. Therefore we kept the old version in
the cache instead of persisting the deleted document. This caused the document
to reappear in the query results until we resolved it via a limbo resolution.
@mikelehen

This comment has been minimized.

Copy link
Member

commented Aug 2, 2018

@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.

mikelehen added a commit that referenced this issue Aug 2, 2018
Fixes decoding WriteResults for deletes (with no updateTime). (#1622)
This should resolve #1591.  We were inadvertantly decoding the WriteResult as
having an updateTime of 0 which caused it to be older than the version of the
document in the RemoteDocumentsCache. Therefore we kept the old version in
the cache instead of persisting the deleted document. This caused the document
to reappear in the query results until we resolved it via a limbo resolution.
@aleh

This comment has been minimized.

Copy link
Author

commented Aug 2, 2018

@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

This comment has been minimized.

Copy link
Author

commented Aug 2, 2018

@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 added a commit that referenced this issue Aug 2, 2018
Fixes decoding WriteResults for deletes (with no updateTime). (#1622)
This should resolve #1591.  We were inadvertantly decoding the WriteResult as
having an updateTime of 0 which caused it to be older than the version of the
document in the RemoteDocumentsCache. Therefore we kept the old version in
the cache instead of persisting the deleted document. This caused the document
to reappear in the query results until we resolved it via a limbo resolution.
mikelehen added a commit that referenced this issue Aug 2, 2018
Fixes decoding WriteResults for deletes (with no updateTime). (#1622)
This should resolve #1591.  We were inadvertantly decoding the WriteResult as
having an updateTime of 0 which caused it to be older than the version of the
document in the RemoteDocumentsCache. Therefore we kept the old version in
the cache instead of persisting the deleted document. This caused the document
to reappear in the query results until we resolved it via a limbo resolution.
@mikelehen

This comment has been minimized.

Copy link
Member

commented Aug 2, 2018

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

This comment has been minimized.

Copy link
Author

commented Aug 2, 2018

@mikelehen Your branch is working properly. Thanks!

wilhuff added a commit that referenced this issue Aug 2, 2018
Fixes decoding WriteResults for deletes (with no updateTime). (#1622)
This should resolve #1591.  We were inadvertantly decoding the WriteResult as
having an updateTime of 0 which caused it to be older than the version of the
document in the RemoteDocumentsCache. Therefore we kept the old version in
the cache instead of persisting the deleted document. This caused the document
to reappear in the query results until we resolved it via a limbo resolution.
ryanwilson added a commit that referenced this issue Aug 2, 2018
Cherry pick fix for #1591 for M30 (#1626)
* Fixes decoding WriteResults for deletes (with no updateTime). (#1622)

This should resolve #1591.  We were inadvertantly decoding the WriteResult as
having an updateTime of 0 which caused it to be older than the version of the
document in the RemoteDocumentsCache. Therefore we kept the old version in
the cache instead of persisting the deleted document. This caused the document
to reappear in the query results until we resolved it via a limbo resolution.

* Add changelog entry for delete WriteResult fix (d9f116). (#1623)

* Actually this fix is going out with 0.13.0

@wilhuff wilhuff added this to the 5.5.0 milestone Aug 3, 2018

@wilhuff

This comment has been minimized.

Copy link
Member

commented Aug 3, 2018

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

@aleh

This comment has been minimized.

Copy link
Author

commented Aug 6, 2018

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

@jhoughjr

This comment has been minimized.

Copy link

commented May 24, 2019

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

This comment has been minimized.

Copy link
Member

commented May 24, 2019

@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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
5 participants
You can’t perform that action at this time.