Firestore: Fix spurious "Backend didn't respond within 10 seconds" errors when network just slow #8145

dconeybe · 2024-04-09T20:40:17Z

Firestore was erroneously concluding that the connection to the backend was broken when the response to the initial listen request was large (e.g. 1000 documents) and the network speed was slow.

This bug resulted in erroneous errors that looked like this:

Could not reach Cloud Firestore backend. Backend didn't respond within 10 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.

The fix is to propagate the first "OPEN" message from WebChannel to the online state detector so that it will consider the connection to be "alive" even though no proto messages have been received on the stream.

Googlers see b/325591749

changeset-bot · 2024-04-09T20:40:21Z

🦋 Changeset detected

Latest commit: d309eaf

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 3 packages

Name	Type
@firebase/firestore	Patch
firebase	Patch
@firebase/firestore-compat	Patch

Not sure what this means? Click here to learn what changesets are.

Click here if you're a maintainer who wants to add another changeset to this PR

google-oss-bot · 2024-04-09T20:56:10Z

Size Report ¹

Affected Products

@firebase/firestore
Type Base (d1eae3a) Merge (e03fd3f) Diff
browser 377 kB 377 kB +275 B (+0.1%)
esm5 362 kB 362 kB +345 B (+0.1%)
main 580 kB 580 kB +464 B (+0.1%)
module 377 kB 377 kB +275 B (+0.1%)
react-native 377 kB 377 kB +275 B (+0.1%)

`bundle`

Type	Base (`d1eae3a`)	Merge (`e03fd3f`)	Diff
firestore (CSI Auto Indexing Disable and Delete)	268 kB	269 kB	+113 B (+0.0%)
firestore (CSI Auto Indexing Enable)	268 kB	269 kB	+113 B (+0.0%)
firestore (Persistence)	303 kB	303 kB	+172 B (+0.1%)
firestore (Query Cursors)	247 kB	241 kB	-6.36 kB (-2.6%)
firestore (Query)	245 kB	238 kB	-6.36 kB (-2.6%)
firestore (Read data once)	233 kB	226 kB	-6.36 kB (-2.7%)
firestore (Read Write w Persistence)	323 kB	323 kB	+172 B (+0.1%)
firestore (Realtime updates)	235 kB	229 kB	-6.36 kB (-2.7%)
firestore (Transaction)	212 kB	205 kB	-6.47 kB (-3.1%)
firestore (Write data)	212 kB	205 kB	-6.39 kB (-3.0%)

firebase
Type Base (d1eae3a) Merge (e03fd3f) Diff
firebase-compat.js 786 kB 786 kB +165 B (+0.0%)
firebase-firestore-compat.js 342 kB 342 kB +165 B (+0.0%)
firebase-firestore.js 436 kB 436 kB +275 B (+0.1%)

Test Logs

https://storage.googleapis.com/firebase-sdk-metric-reports/EdgLCb4PBr.html

google-oss-bot · 2024-04-09T21:07:28Z

Size Analysis Report ¹

This report is too large (568,673 characters) to be displayed here in a GitHub comment. Please use the below link to see the full report on Google Cloud Storage.

Test Logs

https://storage.googleapis.com/firebase-sdk-metric-reports/GoAKfWvA3c.html

thomasdao · 2024-04-13T10:43:11Z

@dconeybe thanks for working on this issue. I tested the PR, the query can load about 100 documents then found the below error

Error: FIRESTORE (10.6.0) INTERNAL ASSERTION FAILED: Unexpected state
    at fail (index.esm2017.js:194:1)
    at __PRIVATE_AsyncQueueImpl.Iu (index.esm2017.js:18538:1)
    at __PRIVATE_AsyncQueueImpl.enqueue (index.esm2017.js:18454:1)
    at __PRIVATE_AsyncQueueImpl.enqueueAndForget (index.esm2017.js:18439:1)
    at DelayedOperation.handleDelayElapsed (index.esm2017.js:15141:1)
    at index.esm2017.js:15123:1

Valansch · 2024-04-14T11:36:36Z

Hi @dconeybe thank you for working on the fix.
Do you have a tip how I can build the sdk and import it as a dart package?

dconeybe · 2024-04-15T15:47:10Z

thomasdao

Please try these steps:

cd packages/firestore
yarn build:debug
cp -r dist ~/YOUR_PROJECT/node_modules/@firebase/firestore

The build:debug script will build dist/index.esm2017.js without all of the optimizations and code mangling. This will make your stack traces easier to interpret.

Now, please reproduce again and post an updated stack trace. Hopefully the stack trace from unmangled code will make more sense.

dconeybe · 2024-04-15T15:51:34Z

Hi @dconeybe thank you for working on the fix. Do you have a tip how I can build the sdk and import it as a dart package?

@Valansch Unfortunately, no, I don't have any experience with dart or flutter. Would you be able to ask this question on the https://github.com/firebase/flutterfire repository?

thomasdao · 2024-04-16T09:40:11Z

@dconeybe please see the error below

Error log

firebase.worker.js:50 Error: FIRESTORE (10.6.0) INTERNAL ASSERTION FAILED: AsyncQueue is already failed: Error: FIRESTORE (10.6.0) INTERNAL ASSERTION FAILED: `pendingResponses` is less than 0. Actual value: -1. This indicates that the SDK received more target acks from the server than expected. The SDK should not continue to operate.
  at fail (index.esm2017.js:213:1)
  at hardAssert (index.esm2017.js:223:1)
  at TargetState.recordTargetResponse (index.esm2017.js:8464:1)
  at index.esm2017.js:8523:1
  at Array.forEach (<anonymous>)
  at WatchChangeAggregator.forEachTarget (index.esm2017.js:8570:1)
  at WatchChangeAggregator.handleTargetChange (index.esm2017.js:8512:1)
  at onWatchStreamChange (index.esm2017.js:20721:1)
  at PersistentListenStream.onMessage (index.esm2017.js:20010:1)
  at index.esm2017.js:19945:1
  at fail (index.esm2017.js:213:1)
  at AsyncQueueImpl.verifyNotFailed (index.esm2017.js:25633:1)
  at AsyncQueueImpl.enqueue (index.esm2017.js:25539:1)
  at AsyncQueueImpl.enqueueAndForget (index.esm2017.js:25521:1)
  at DelayedOperation.handleDelayElapsed (index.esm2017.js:21168:1)
  at index.esm2017.js:21145:1

dconeybe · 2024-04-16T14:58:41Z

@thomasdao Thanks for providing the updated stack trace. That error looks like the bug that you reported in #7652 has resurfaced. That is surprising because the bug you reported should have been fixed in v10.5.2 (and you are using v10.6.0).

To rule out this issue, could you try the following:

Upgrade your dependency on firebase in package.json to the latest: "firebase": "^10.11.0"
Delete your package-lock.json and node_modules directory.
Run npm install in your application.
Make sure that the firebase-js-sdk that you checked out from GitHub is at the latest commit in the master branch.

Thanks!

thomasdao · 2024-04-16T15:20:35Z

@dconeybe I updated Firebase to 10.11.0, then copy the firestore dist folder, and the query still hangs with below error:

index.esm2017.js:78 [2024-04-16T15:19:20.510Z]  @firebase/firestore: Firestore (10.11.0): WebChannelConnection RPC 'Listen' stream 0x5a8c4d87 transport errored: 
Qd {type: 'c', target: Q, g: Q, defaultPrevented: false, status: 1}

dconeybe · 2024-04-16T15:43:15Z

@thomasdao Can you confirm that you have the dconeybe/WebChannelOnOpenFix_Bug325591749 branch checked out in your local clone of this repository? If so, could you try re-running the yarn build:debug and cp -r dist ~/YOUR_PROJECT/node_modules/@firebase/firestore steps?

Also, if you're willing, could you enable Firestore debug logging (i.e. call setLogLevel('debug')) and provide the entire log that is produced? Feel free to email your log to me directly (my email is my github username at google.com) if you're concerned about posting the logs publicly.

thomasdao · 2024-04-17T02:14:22Z

@dconeybe I've sent the debug log to your email. I've checked the branch again and it's correct:

$ git pull
Already up to date.

$ git rev-parse --abbrev-ref HEAD
dconeybe/WebChannelOnOpenFix_Bug325591749

$ git branch --show-current
dconeybe/WebChannelOnOpenFix_Bug325591749

dconeybe · 2024-04-17T18:48:52Z

@thomasdao Thank you for sending me the logs. Unfortunately, based on the logs I can confirm that this PR will NOT fix the issue you are reporting (#7860). One thing, however, that I noticed from your logs is that your app seems to using Firestore before a user is signed in, and then continue to use it after the user is signed in. This could be innocuous, or could be undesirable behavior, depending on what your app is doing. I just wanted to point it out.

…_Bug325591749

…lConnection sends

MarkDuckworth

LGTM with comments.

MarkDuckworth · 2024-04-18T16:30:12Z

packages/firestore/src/remote/connection.ts

@@ -113,6 +113,7 @@ export interface Connection {
 * be called if the stream successfully established a connection.


Can you clarify the difference between onOpen and onConnected in the documentation? Currently the docs state that "onOpen will only be called if the stream successfully established a connection." That definition of onOpen is what I would expect for onConneted.

I've updated the docs. LMK if they clarify.

The naming "onOpen" is somewhat unfortunate, as it does not actually indicate that an opened connection with the backend has been established. I think at one point this was the meaning, but the channel is now optimized to send the "handshake" with the first message to avoid an extra round-trip with the backend. So WebChannelConnection now sends onOpen as soon as it is ready to send a message so that it can send the handshake along with the first message. I added onConnected to send an event when an actual connection with the backend has been established.

MarkDuckworth · 2024-04-18T16:37:32Z

packages/firestore/test/integration/remote/stream.test.ts

@@ -148,6 +156,14 @@ describe('Watch Stream', () => {
 });
 });
 });
+
+ it('gets connected event before first message', () => {


I find the title of this a little misleading because the test doesn't appear to test for any messages. Or does it and I'm just not seeing how?

The awaitCallback() will fail if some other callback occurs (such as a message). The test doesn't care about if the "message" callback occurs, only that "connected" occurs before it. Does that clarify?

…nOpen and onConnected

thomasdao · 2024-04-18T21:54:45Z

One thing, however, that I noticed from your logs is that your app seems to using Firestore before a user is signed in, and then continue to use it after the user is signed in.

@dconeybe beside user data, I also store public settings in Firestore, so I need to setup Firestore even if the user does not sign in.

dconeybe added 4 commits April 9, 2024 16:00

stream_bridge.ts: Add onConnected to StreamBridge

68d5ba9

deliver connected notification

5ebe413

yarn prettier

fe73412

yarn changeset

553a55c

dconeybe added the api: firestore label Apr 9, 2024

dconeybe self-assigned this Apr 9, 2024

dconeybe mentioned this pull request Apr 12, 2024

Hanging query for Firestore #7860

Open

dconeybe added 4 commits April 17, 2024 14:50

Merge remote-tracking branch 'origin/master' into WebChannelOnOpenFix…

e962a73

…_Bug325591749

grpc_connection.ts: synthesize the 'onConnected' event that WebChanne…

0edcf63

…lConnection sends

stream.test.ts: fix tests to accommodate the new "onConnected" event.

b649483

webchannel.test.ts: add missing onConnected callback

590d5af

dconeybe marked this pull request as ready for review April 18, 2024 14:55

dconeybe requested review from a team as code owners April 18, 2024 14:55

MarkDuckworth approved these changes Apr 18, 2024

View reviewed changes

remote/connection.ts: update docs to clarify the difference between o…

d309eaf

…nOpen and onConnected

dconeybe merged commit 2244194 into master Apr 18, 2024
44 checks passed

dconeybe deleted the dconeybe/WebChannelOnOpenFix_Bug325591749 branch April 18, 2024 17:47

dconeybe mentioned this pull request Apr 18, 2024

Firestore experimentalAutoDetectLongPolling/experimentalForceLongPolling does not work as expected #8176

Closed

google-oss-bot mentioned this pull request Apr 24, 2024

Version Packages #8202

Merged

alex-dokienko mentioned this pull request Apr 27, 2024

[firebase_core]: Error Encountered After Upgrading Firebase Core to v2.30.1: Invalid Conditional Import in _flutterfire_internals Package firebase/flutterfire#12708

Open

1 task

firebase locked and limited conversation to collaborators May 19, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Firestore: Fix spurious "Backend didn't respond within 10 seconds" errors when network just slow #8145

Firestore: Fix spurious "Backend didn't respond within 10 seconds" errors when network just slow #8145

dconeybe commented Apr 9, 2024 •

edited

changeset-bot bot commented Apr 9, 2024 •

edited

google-oss-bot commented Apr 9, 2024 •

edited

`@firebase/firestore`

`bundle`

`firebase`

google-oss-bot commented Apr 9, 2024 •

edited

thomasdao commented Apr 13, 2024 •

edited

Valansch commented Apr 14, 2024

dconeybe commented Apr 15, 2024

dconeybe commented Apr 15, 2024

thomasdao commented Apr 16, 2024

dconeybe commented Apr 16, 2024

thomasdao commented Apr 16, 2024

dconeybe commented Apr 16, 2024

thomasdao commented Apr 17, 2024 •

edited

dconeybe commented Apr 17, 2024

MarkDuckworth left a comment

MarkDuckworth Apr 18, 2024

dconeybe Apr 18, 2024

MarkDuckworth Apr 18, 2024

dconeybe Apr 18, 2024

thomasdao commented Apr 18, 2024

		@@ -113,6 +113,7 @@ export interface Connection {
		* be called if the stream successfully established a connection.

Firestore: Fix spurious "Backend didn't respond within 10 seconds" errors when network just slow #8145

Firestore: Fix spurious "Backend didn't respond within 10 seconds" errors when network just slow #8145

Conversation

dconeybe commented Apr 9, 2024 • edited

changeset-bot bot commented Apr 9, 2024 • edited

🦋 Changeset detected

google-oss-bot commented Apr 9, 2024 • edited

Size Report 1

Affected Products

@firebase/firestore

bundle

firebase

Test Logs

google-oss-bot commented Apr 9, 2024 • edited

Size Analysis Report 1

Test Logs

thomasdao commented Apr 13, 2024 • edited

Valansch commented Apr 14, 2024

dconeybe commented Apr 15, 2024

dconeybe commented Apr 15, 2024

thomasdao commented Apr 16, 2024

dconeybe commented Apr 16, 2024

thomasdao commented Apr 16, 2024

dconeybe commented Apr 16, 2024

thomasdao commented Apr 17, 2024 • edited

dconeybe commented Apr 17, 2024

MarkDuckworth left a comment

Choose a reason for hiding this comment

MarkDuckworth Apr 18, 2024

Choose a reason for hiding this comment

dconeybe Apr 18, 2024

Choose a reason for hiding this comment

MarkDuckworth Apr 18, 2024

Choose a reason for hiding this comment

dconeybe Apr 18, 2024

Choose a reason for hiding this comment

thomasdao commented Apr 18, 2024

dconeybe commented Apr 9, 2024 •

edited

changeset-bot bot commented Apr 9, 2024 •

edited

google-oss-bot commented Apr 9, 2024 •

edited

Size Report ¹

`@firebase/firestore`

`bundle`

`firebase`

google-oss-bot commented Apr 9, 2024 •

edited

Size Analysis Report ¹

thomasdao commented Apr 13, 2024 •

edited

thomasdao commented Apr 17, 2024 •

edited