infinite setTimeout loops after upgrading to 9.9.1

[hsubox76]

Reposting new issue spawned from #6373

Issue reporter says:

I'm pretty sure this change (firebase 9.9.1) is causing infinite setTimeouts on reflect.app - we've just had to revert back to 9.9.0.

The 9.9.1 change is referring to the fix described in this comment:
#6373 (comment)

The PR that comment is referring to is:
#6439

[hsubox76]

Is it possible to provide a minimal reproduction of this infinite setTimeouts issue? I'm assuming this is a new issue introduced by the "throttle fix" in 9.9.1 and not the original sleep/wake issue, and if so, can you create a new issue and provide the minimal reproduction, or at least a sample of the code that leads to these errors, or logs?

I can't give you a minimal reproduction, but I can give you a version of the app with the issue if that helps?

All we did was upgrade firebase to 9.9.4. I tried each version until 9.0.0 (which fixed the issue).

Anything would be helpful, a minimal reproduction would be best, the full app code would be useful as well, especially if you can point out where in the code App Check is used. If you only have an app build that demonstrates the problem, I can try to work with that.

Which AppCheck-enabled products are you using? Firestore/RTDB/Functions/Storage?

[maccman]

Here's the source code of our firebase configuration:
https://gist.github.com/maccman/ef20fcff626f867a41782a4e652d7832

Here's the live app showing the issue: https://alex-next.reflect.app/app

And a demo video:
https://user-images.githubusercontent.com/2142/190552728-bf5d77ca-5136-45e5-9aa7-f21c512726bf.mp4

[hsubox76]

Thanks for all the information. I was able to reproduce the behavior in the video by using the live app and substituting a logging version of window.setTimeout. A couple of things stood out:

1. What was the original symptom of the bug? Did this cause slowdowns in the app or did something show up in performance metrics? I didn't notice any but I'm not familiar with how the app normally works. I'm just curious what led you to looking at setTimeouts.

2. The args being logged indicate the setTimeout is being called by this line of Firestore code

   firebase-js-sdk/packages/firestore/src/util/async_queue.ts

   Line 156 in bcbd1d6

   this.timerHandle = setTimeout(() => this.handleDelayElapsed(), delayMs);

   That doesn't mean it's not an App Check issue, especially as Firestore uses App Check, but I'll need to bring in the Firestore team to see if they can shed some light on this. But it looks like it's not recursion, it looks like it's called every time a certain kind of Firestore operation is enqueued?

3. Also this may be a minor thing but I didn't notice App Check in the source code provided. Is it initialized in the ./firebase-packages file that is imported?

Edit: The only change in Firestore between 9.9.0 and 9.9.1 seems to be updating the grpc-loader dependency which I don't think would be related to any kind of slowdown or excessive setTimeout calls. https://github.com/firebase/firebase-js-sdk/pull/6442/files

[maccman]

Thanks! Glad you were able to reproduce.

1. Original symptons were pegging cpu. Unfortunately I have a pretty fast laptop so I didn't notice. One of our customers raised it. Looking at timeouts was a lucky guess.
2. Yes I don't think we use App Check. I just thought it might be related given the similar symptoms on that other thread.

It's possible that this is caused by some kind of internal state issue with locally cached data? Just an idea.

[MarkDuckworth]

@maccman, looks like this was fixed in #6585, which should have been released in 9.10.0 on Sept 15th. Can you update and let me know if you're still having the issue?

[maccman]

That seems to have fixed it. Thank you!

[maccman]

Do you think this deserves a bit of a post mortem? I.e. how it happened, how many users affected, steps to prevent that happening again etc.