Firestore query doesn't resolve with response received from server immediately

[rishisv]

[REQUIRED] Describe your environment

• Operating System version: Mac OS v12.5
• Browser version: Chrome v104
• Firebase SDK version: 8.10 (web sdk) and 9.9.2 (web sdk)
• Firebase Product: storage (firestore)

[REQUIRED] Describe the problem

We are seeing delays of a minute before our Firestore query resolves. In debug logs, we see the response immediately from the server but the query does not resolve. Instead there is a delay for about a minute without any logs. Post this delay, we see logs around memory persistence transaction and then the query resolves.

We have not enabled persistence in our web application, we are using web sdk v8.10

We are hitting this issue in production frequently.

Steps to reproduce:

Attaching firebase debug logs:

[2022-08-09T09:07:55.435Z]  @firebase/firestore: Firestore (8.10.0): Connection WebChannel received: {"documentChange":{"document":{"name":"targetIds":[26]}}
------> All data received from server at this point
[2022-08-09T09:07:55.435Z]  @firebase/firestore: Firestore (8.10.0): Connection WebChannel received: {"targetChange":{"targetIds":[26],"resumeToken":"CgkIiuTFpLS5+QI=","readTime":"2022-08-09T09:07:55.057674Z"}}
------>
------> Delay here, no logs during this time
------>
[2022-08-09T09:08:42.807Z]  @firebase/firestore: Firestore (8.10.0): Connection WebChannel received: {"targetChange":{"targetChangeType":"CURRENT","targetIds":[26],"resumeToken":"CgkItNrHpLS5+QI=","readTime":"2022-08-09T09:07:55.089204Z"}}
[2022-08-09T09:08:42.927Z]  @firebase/firestore: Firestore (8.10.0): Connection WebChannel received: {"targetChange":{"resumeToken":"CgkItNrHpLS5+QI=","readTime":"2022-08-09T09:07:55.089204Z"}}
[2022-08-09T09:08:42.927Z]  @firebase/firestore: Firestore (8.10.0): MemoryPersistence Starting transaction: Get last remote snapshot version
[2022-08-09T09:08:42.927Z]  @firebase/firestore: Firestore (8.10.0): MemoryPersistence Starting transaction: Apply remote event
[2022-08-09T09:08:42.933Z]  @firebase/firestore: Firestore (8.10.0): MemoryPersistence Starting transaction: notifyLocalViewChanges
[2022-08-09T09:08:42.935Z]  @firebase/firestore: Firestore (8.10.0): MemoryPersistence Starting transaction: Release target
instrument.js?b344:109 [2022-08-09T09:08:42.938Z]  @firebase/firestore: Firestore (8.10.0): Connection WebChannel sending: {"database":"projects/production/databases/(default)","removeTarget":20}
[2022-08-09T09:08:42.944Z]  @firebase/firestore: Firestore (8.10.0): MemoryPersistence Starting transaction: Release target

----> Query resolves here

[dconeybe]

Hello @rishisv. Thank you for the bug report. I notice that you've reported this bug against v8.10.0. This is an old version of the SDK that we no longer maintain (it only gets emergency security fixes). Could you reproduce this with the latest version of the SDK, which is 9.9.2 at the time of writing?

[rishisv]

Thank you @dconeybe for your response, appreciate you looking into our report. We have reproduced similar delay with v9.9.2, logs pasted below.

[2022-08-10T08:17:46.349Z]  @firebase/firestore: Firestore (9.9.2): Connection WebChannel received: {"documentChange":{"document": ..... }}
<------- all data for query received from server at this point
[2022-08-10T08:17:46.350Z]  @firebase/firestore: Firestore (9.9.2): Connection WebChannel received: {"targetChange":{"targetIds":[26],"resumeToken":"CgkIoPu1+Oq7+QI=","readTime":"2022-08-10T08:17:45.950624Z"}}
------>
------> Delay here, no logs during this time
------>
[2022-08-10T08:18:18.686Z]  @firebase/firestore: Firestore (9.9.2): Connection WebChannel received: {"targetChange":{"targetChangeType":"CURRENT","targetIds":[26],"resumeToken":"CgkIkcO2+Oq7+QI=","readTime":"2022-08-10T08:17:45.959825Z"}}
[2022-08-10T08:18:18.791Z]  @firebase/firestore: Firestore (9.9.2): Connection WebChannel received: {"targetChange":{"resumeToken":"CgkIkcO2+Oq7+QI=","readTime":"2022-08-10T08:17:45.959825Z"}}
[2022-08-10T08:18:18.791Z]  @firebase/firestore: Firestore (9.9.2): MemoryPersistence Starting transaction: Get last remote snapshot version
[2022-08-10T08:18:18.792Z]  @firebase/firestore: Firestore (9.9.2): MemoryPersistence Starting transaction: Apply remote event
[2022-08-10T08:18:18.800Z]  @firebase/firestore: Firestore (9.9.2): MemoryPersistence Starting transaction: notifyLocalViewChanges
[2022-08-10T08:18:18.802Z]  @firebase/firestore: Firestore (9.9.2): MemoryPersistence Starting transaction: Release target
[2022-08-10T08:18:18.805Z]  @firebase/firestore: Firestore (9.9.2): Connection WebChannel sending: {"database":"projects/production/databases/(default)","removeTarget":20}
[2022-08-10T08:18:18.812Z]  @firebase/firestore: Firestore (9.9.2): MemoryPersistence Starting transaction: Release target
[2022-08-10T08:18:18.813Z]  @firebase/firestore: Firestore (9.9.2): Connection WebChannel sending: {"database":"projects/production/databases/(default)","removeTarget":26}
[2022-08-10T08:18:18.823Z]  @firebase/firestore: Firestore (9.9.2): MemoryPersistence Starting transaction: Allocate target

[dconeybe]

This is very interesting. The delay in raising the snapshot that you are experiencing is expected based on the log you provided. A snapshot doesn't get raised until there is a CURRENT followed by a "global snapshot" (which is the log line following the "targetChangeType":"CURRENT" line).

The question then is why is there a delay? Is the backend delaying sending the CURRENT and global snapshot messages? Or is the client thrashing, blocking, or otherwise delayed from processing those messages when they get received? Does anything come to mind that may be blocking the thread that would delay processing the messages the client receives from Firestore?

Is there any chance that you would be able to try the same query using the Android SDK or the iOS SDK?

Is it possible that your app runs behind a buffering proxy? If so, follow the instructions at #1674 to force-enable "long polling" to see if this fixes your issue. Also try browsing to the https://debug-my.firebaseapp.com/ site (as documented in that linked issue) to see if that test detects an incompatible buffering proxy.

Finally, could you post a code snippet that reproduces the issue for you? It looks like you're just calling getDoc() but it would be helpful to know for sure.

[rishisv]

We see this issue with more than one query and it is not on a specific page or time, we are continuing to look into our app to see if there is any blocking but we found none yet. During this delay, rest/subsequent firestore queries are blocked too. But the app renders other pages and site fine (hinting that there is no blocking in rest of the app). We also checked using firestore-lite query getDocs and we saw no delay. So this is specific to firestore sdk client.

Our app is static generated client side rendered (next.js) and deployed with firebase hosting (firestore in asia-southeast1 region). We haven't yet seen/reproduced this issue on our staging site in us-west region though on staging we don't have much traffic/users.

Not running behind any proxy. All tests on https://debug-my.firebaseapp.com/ are successful. We have also turned on experimentalForceLongPolling.

We are seeing above delays on code snippets that invoke a firestore query. We shall try to see if we can reproduce on an online code sandbox and share if we are.

Appreciate your help here @dconeybe, thank you for helping us with this issue.

[dconeybe]

Thank you for this information. Allow me to summarize to make sure I understand correctly. Please correct any incorrect statements.

1. So far this issue has only been reproduced in asia-southeast1; namely, it hasn't been observed in us-west.
2. The queries only occasionally experience the delay; sometimes they complete in a timely manner and other times they suffer from this delay.
3. There is not one particular query that suffers from the delay; various queries are affected at various times.

Thank you for testing out long polling. It was a long shot, but worth a try.

You mention that rest/subsequent firestore queries are blocked too. This sounds like Firestore's AsyncQueue (an internal queue of Firestore's background work) is blocked. If you're able to reproduce this delay, could you check to see what Firestore is doing during that delay? Is there a method that it appears to be blocked in?

Is there a way that you could demo the bug (e.g. capture a video) or provide me a link where I could reproduce it myself?

[rishisv]

@dconeybe summary you have posted above on the issue we are seeing is correct. Any suggestions on how we can check to see what Firestore is doing during the delay beyond the firestore debug logs we shared earlier? we shall also try to log around all our firestore calls in our app to check too. We are also trying to create a reproduction outside of our app and share, in the mean time shall email you link/details.

[dconeybe]

Thanks for sending me the link. I was indeed able to reproduce the delay you are referring to. It appears to be a delay in the backend sending the "CURRENT" message followed by the "global snapshot" message. Looking at the web logs, my first guess is that it is the sheer amount of data being downloaded that may be contributing to the delay. The main culprit seems to be the "accessControlList" field on the documents in the "posts" collection, which is a long (seemingly unbounded) string array. It could also be related to other queries or writes that are running that I'm not aware of. My guess is that this isn't reproducible in an isolated test app because the amount of data/traffic just isn't large enough to cause a noticeable delay.

The maintainers of this repository (such as me) are, unfortunately, not in a position to investigate backend issues like this. I'd recommend filing a support ticket, such as with https://firebase.google.com/support.

I do have one final question though: Is this bug reproducible in your Android app? Since this seems to be a backend issue with queries just taking a long time, I'd expect to see the same sort of delay with the Android app as well.

If you do end up finding a problematic query, one workaround could be to use a separate Firestore instance for those long-running queries. That way the two Firestore instances would maintain their own distinct connections to the backend and the long-running queries would not hold up the otherwise-fast queries. The drawback of this approach would be that they would not share local caches and could be out of sync with each other.

I hope this helps. I'll leave this ticket opened for now, but I don't think there is much more that I can do to assist.

[rishisv]

Thank you for checking out the link and sharing more insights. Thank you for suggesting the workaround to use two Firestore instances. Our android app is an embedded web view loading our responsive web app so the code is identical and we see the same issue there.

I should point out that we have used Firestore-lite in place of these Firestore queries with delays as a workaround. But we would rather not replace all FS queries in the app with Firestore-lite, in many places we need subscribed updates.

I should also clarify that the delay happens after the server responds with all the data. We also see the delay with other queries which do not transfer a lot of data. So it’s interesting that the delay is after the server responds with data. It is also strange that this delay is not consistent though frequent.

Can you please shed more light on the CURRENT message and global snapshot messages if you can? Anything to do with waiting on in flight transactions in the backend that could cause a delay in the backend sending these messages? Though these docs shouldn’t see transactional writes or updates frequently.

Thank you so much for looking into our issue, appreciate your efforts and time looking into our project.

[dconeybe]

It makes sense that you wouldn't experience these delays using firestore-lite since the "lite" sdk uses a different, simpler mechanism to interact with the backend servers. For example, there are no efforts to keep all queries in "sync", and there is no offline persistence or realtime updates with the "lite" sdk.

And thank you for answering the question about your Android app. That makes sense.

The "CURRENT" message just means that the initial results for the query have now all been transmitted to the client. Any document changes/removes/deletes thereafter are a delta on top of that initial document set. The "global snapshot" means that all active queries have been updated to the same point in time and will all be consistent with each other. The "global snapshot" is the signal that the client SDKs use to emit the snapshots. This is why you see all of the data transmitted to the client, but it's just sitting in a buffer in memory and the client is waiting for the "global snapshot" message to release it. So if there is one query that is delaying the global snapshot then this one query holds up snapshots for all queries. So if you can find a culprit query and move it to a different Firestore instance then that could solve your problem. I should be clear that this is just a guess at this point though. It could be something completely different that is delaying the current and global snapshot messages.

[google-oss-bot]

Hey @rishisv. We need more information to resolve this issue but there hasn't been an update in 5 weekdays. I'm marking the issue as stale and if there are no new updates in the next 5 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

[google-oss-bot]

Since there haven't been any recent updates here, I am going to close this issue.

@rishisv if you're still experiencing this problem and want to continue the discussion just leave a comment here and we are happy to re-open this.