Hanging Firestore queries on version 10.4.0

[thomasdao]

Operating System

Both Mac and Windows

Browser Version

Electron 24.8.3

Firebase SDK Version

10.4.0

Firebase SDK Product:

Auth, Firestore, Functions, Storage

Describe your project's tooling

Electron 24.8.3

Describe the problem

Hi, since we updated Firebase to 10.4.0, we have received multiple reports from our users that they can't retrieve the data from Firestore server. We then downgraded to 10.3.1 and these users can retrieve data normally. From the release note, we believe this is related:

Fixed an issue where Cloud Firestore was incorrectly using XHR instead of fetch for streaming response.

Updated dependency grpc-js from version ~1.8.17 to ~1.9.0.

I also noticed that on 10.4.0, our query becomes a lot slower and frequently cannot complete. Switch back to 10.3.1 and the query becomes a lot faster.

Steps and code to reproduce issue

This issue only happens for 10.4.0.

[thomasdao]

When I set the log level to debug, there're a lot of messages in the console as below, but I'm not sure if it's related:

[2023-09-27T04:11:34.774Z]  @firebase/firestore: Firestore (10.4.0): WatchChangeAggregator Detected inactive target 10
index.esm2017.js:78 [2023-09-27T04:11:34.774Z]  @firebase/firestore: Firestore (10.4.0): WatchChangeAggregator Detected inactive target 42
index.esm2017.js:78 [2023-09-27T04:11:34.774Z]  @firebase/firestore: Firestore (10.4.0): WatchChangeAggregator Detected inactive target 44
index.esm2017.js:78 [2023-09-27T04:11:34.774Z]  @firebase/firestore: Firestore (10.4.0): WatchChangeAggregator Detected inactive target 46
index.esm2017.js:78 [2023-09-27T04:11:34.774Z]  @firebase/firestore: Firestore (10.4.0): WatchChangeAggregator Detected inactive target 48
index.esm2017.js:78 [2023-09-27T04:11:34.774Z]  @firebase/firestore: Firestore (10.4.0): WatchChangeAggregator Detected inactive target 50
index.esm2017.js:78 [2023-09-27T04:11:34.774Z]  @firebase/firestore: Firestore (10.4.0): WatchChangeAggregator Detected inactive target 52
index.esm2017.js:78 [2023-09-27T04:11:34.774Z]  @firebase/firestore: Firestore (10.4.0): WatchChangeAggregator Detected inactive target 54
index.esm2017.js:78 [2023-09-27T04:11:34.774Z]  @firebase/firestore: Firestore (10.4.0): MemoryPersistence Starting transaction: Get last remote snapshot version
index.esm2017.js:78 [2023-09-27T04:11:34.775Z]  @firebase/firestore: Firestore (10.4.0): MemoryPersistence Starting transaction: Apply remote event
index.esm2017.js:78 [2023-09-27T04:11:34.777Z]  @firebase/firestore: Firestore (10.4.0): MemoryPersistence Starting transaction: notifyLocalViewChanges
index.esm2017.js:78 [2023-09-27T04:11:34.777Z]  @firebase/firestore: Firestore (10.4.0): MemoryPersistence Starting transaction: Release target
index.esm2017.js:78 [2023-09-27T04:11:34.780Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 sending: {"database":"projects/xxxxxx/databases/(default)","removeTarget":30}
index.esm2017.js:78 [2023-09-27T04:11:34.785Z]  @firebase/firestore: Firestore (10.4.0): MemoryPersistence Starting transaction: Release target
index.esm2017.js:78 [2023-09-27T04:11:34.788Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 sending: {"database":"projects/xxxxxx/databases/(default)","removeTarget":32}
index.esm2017.js:78 [2023-09-27T04:11:34.793Z]  @firebase/firestore: Firestore (10.4.0): MemoryPersistence Starting transaction: Release target
index.esm2017.js:78 [2023-09-27T04:11:34.796Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 sending: {"database":"projects/xxxxxx/databases/(default)","removeTarget":34}
index.esm2017.js:78 [2023-09-27T04:11:34.802Z]  @firebase/firestore: Firestore (10.4.0): MemoryPersistence Starting transaction: Release target
index.esm2017.js:78 [2023-09-27T04:11:34.805Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 sending: {"database":"projects/xxxxxx/databases/(default)","removeTarget":36}
index.esm2017.js:78 [2023-09-27T04:11:34.809Z]  @firebase/firestore: Firestore (10.4.0): MemoryPersistence Starting transaction: Release target
index.esm2017.js:78 [2023-09-27T04:11:34.812Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 sending: {"database":"projects/xxxxxx/databases/(default)","removeTarget":38}
index.esm2017.js:78 [2023-09-27T04:11:34.817Z]  @firebase/firestore: Firestore (10.4.0): MemoryPersistence Starting transaction: Release target
index.esm2017.js:78 [2023-09-27T04:11:34.820Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 sending: {"database":"projects/xxxxxx/databases/(default)","removeTarget":40}
index.esm2017.js:78 [2023-09-27T04:11:34.881Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 received: {"targetChange":{"targetChangeType":"ADD","targetIds":[42]}}
index.esm2017.js:78 [2023-09-27T04:11:34.882Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 received: {"targetChange":{"targetChangeType":"ADD","targetIds":[44]}}
index.esm2017.js:78 [2023-09-27T04:11:34.882Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 received: {"targetChange":{"targetChangeType":"ADD","targetIds":[46]}}
index.esm2017.js:78 [2023-09-27T04:11:34.882Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 received: {"targetChange":{"targetChangeType":"ADD","targetIds":[48]}}
index.esm2017.js:78 [2023-09-27T04:11:34.882Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 received: {"targetChange":{"targetChangeType":"ADD","targetIds":[50]}}
index.esm2017.js:78 [2023-09-27T04:11:34.882Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 received: {"targetChange":{"targetChangeType":"ADD","targetIds":[52]}}
index.esm2017.js:78 [2023-09-27T04:11:34.882Z]  @firebase/firestore: Firestore (10.4.0): WebChannelConnection RPC 'Listen' stream 0x3e730da7 received: {"targetChange":{"targetChangeType":"ADD","targetIds":[54]}}

[dconeybe]

Drive-by comment: I'm looking into another issue that has those strange "Detected inactive target" log messages: #7641. I wonder if that is related to this one.

@thomasdao: Can you provide a longer debug log than the one in your comment above? I'm quite interested to see what log messages appeared before the "Detected inactive target" log messaged.

[thomasdao]

Hi @dconeybe, I can send you the whole debug log, however since it contains some private data, how do I send it to you? Thanks!

[dconeybe]

Hi @dconeybe, I can send you the whole debug log, however since it contains some private data, how do I send it to you?

The best way would be to go to https://firebase.google.com/support, select "Bugs and Features", select "Bug Report", and open a bug. You can attach the log to that bug. Note that there is a disclaimer about PII at the bottom of that page so make sure that you're okay with that before uploading your logs. Make sure to include the URL of this GitHub issue in the issue's description as well as my username. The ticket should get routed to me, but it could take a day or two. I'm especially interested in the "addTarget" and "removeTarget" messages, in addition to the logs messages that you've already posted.

Alternately, feel free to redact the sensitive information from the log before posting it, such as the database ID, document names, and document contents, and post the logs publicly.

Could you tell me, are the documents that seem to be causing this problem "large", in that they have a lot of fields?

[thomasdao]

Hi @dconeybe, I added the log below, some data has been redacted with <<< Data received >>>. For easier comparison, I attach the log for both 10.3.1 and 10.4.0.

For 10.3.1, the query completed within a few seconds, but for 10.4.0, the query still stucks for more than 10 minutes at the time I took the log. Even if I waited longer, Firebase did not print any more log, so it looks like the query is stuck.

Could you tell me, are the documents that seem to be causing this problem "large", in that they have a lot of fields?

My document contains around 10 fields, usually less than 100KB. I used pagination to retrieve data, each page contains only 100 documents.

Log for 10.4.0: https://drive.google.com/file/d/1yHTwXPLw9FWi7M5ZWV4Ije-cNw8fnbVH/view?usp=sharing

Log for 10.3.1: https://drive.google.com/file/d/1Dq7ypEXYp1BLEwIXGOH_pYdHbMIBq3TE/view?usp=sharing

[dconeybe]

Update: After comparing the logs for this issue with the logs from the potentially-related issue #7641, it appears that they are distinct issues with the same presenting problem (i.e. the callback registered with onSnapshot() is not being called).

Namely, in #7641 the root cause appears to be the server sending multiple targetChangeType=ADD messages for a single target, causing the client's internal state to become invalid and erroneously discard the document data that it is sent. In comparison, the logs for this issue do not show multiple targetChangeType=ADD messages for a single target (i.e. they show exactly 1 such message, as expected), leading me to conclude that it has a different root cause and needs to be investigated independently.

[MarkDuckworth]

@thomasdao, This would be easiest to diagnose if we can reproduce it. Can you provide some example code that shows us what your application is doing, or preferably, can you provide a minimal reproducible example electron app?

Also, since an Electron app has both node.js and chromium processes, we inferred from the logs that the failing code is running in chromium/browser window. Can you confirm that your affected code is only running in the browser window? If so, this rules out the grpc-js version change.