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

onAuthStateChanged hangs on startup at PersistenceManager.create step #8482

Open
GaurangTandon opened this issue Sep 5, 2024 · 10 comments
Open

Comments

@GaurangTandon
Copy link

Operating System

Windows

Environment (if applicable)

Chrome 128

Firebase SDK Version

10.11.0

Firebase SDK Product(s)

Auth

Project Tooling

MV3 Chrome extension service worker built using webpack

Detailed Problem Description

Problem

onAuthStateChanged() hangs on extension service worker startup and then remains hanged until the extension service worker is restarted (either by restarting the browser or by manually reloading the extension). Note that we are using indexeddb persistence so we expect the Firebase instance to get logged in automatically whenever the service worker restarts.

Logging details

We added logging into the underlying @firebase/auth package using npx patch-package, and got the hang on this case:

tbLog('IWP: creating'); // <-- this line got printed
this.persistenceManager = await PersistenceUserManager.create(this, persistenceHierarchy); // <-- hanged here
tbLog('IWP: created'); // <-- this line never got printed

PS: Let us know if you need additional logging inside the Firebase Auth package, and what exactly. It can take us a few days to get the data.

Steps and code to reproduce issue

We have roughly the following setup:

import { getAuth, onAuthStateChanged, } from 'firebase/auth/web-extension';

const firebaseApp = initializeApp(firebaseConfig);
const firestore = initializeFirestore(firebaseApp, {
  experimentalForceLongPolling: true
});
onAuthStateChanged(getAuth(firebaseApp), (user) => {
  console.log(user);
  if (user) {
    enableIndexedDbPersistence(firestore, { forceOwnership: true });
  }
}});

Note that we are using the web-extension entrypoint into firebase/auth. Note that we initialize persistence after auth has enabled. I'm not sure if it should be the other way around, I couldn't find any official docs around it, or if that matters at all.

I have attached the patch file generated using patch-package.
@firebase+auth+1.7.1.patch

@GaurangTandon GaurangTandon added new A new issue that hasn't be categoirzed as question, bug or feature request question labels Sep 5, 2024
@google-oss-bot
Copy link
Contributor

I couldn't figure out how to label this issue, so I've labeled it for a human to triage. Hang tight.

@jbalidiong jbalidiong added api: auth needs-attention and removed needs-triage new A new issue that hasn't be categoirzed as question, bug or feature request labels Sep 5, 2024
@DellaBitta
Copy link
Contributor

Hi @GaurangTandon,

Could it be that those operations are throwing errors instead of hanging? Could you try catching any error and logging if one is encountered?

Also, there's a pretty lengthy and informative thread about Firestore and persistence in Web Workers in #7364 that's worth reviewing.

Thanks!

@GaurangTandon
Copy link
Author

Hi @DellaBitta I added more logging last week and got some updated logs today. Updated patch file:
@firebase+auth+1.7.1.patch

Inside _openDatabase function, the logs PC: 3 then IA: 0 then OD: init got printed, but none of the other logs get printed after it. This implies that either:

  1. the promise got created, but the 'success', 'upgradeneeded', or the 'success' events did not fire, or
  2. the indexedDB.open function itself threw an exception.

I read the linked issue, thanks for sharing. For Web Workers, I understand more than one website tab can be open at the same time. However, in Chrome extensions, at most one extension service worker is going to be running at a given time.

@GaurangTandon
Copy link
Author

Update: I don't think alternative 2 is possible. If indexedDB.open threw an exception, then _openDatabase() would reject, and it would be caught in the try...catch of the _isAvailable function, and we would see PC: 4 printed. But I don't see PC: 4 in the logs. OD: init is the last log line.

@DellaBitta
Copy link
Contributor

Hi @GaurangTandon,

Thanks so much for clarifying all of this. We're still working to try to reproduce the problem. In the meantime, could you add another log after the line that creates the IndexedDB request? It'd be helpful to know if that operation is returning:

tbLog('OD: init');
const request = indexedDB.open(DB_NAME, DB_VERSION);
tbLog('OD: request created');

Perhaps even log the request object as well.

Also, I've noticed that the Auth code creates a listener for the success, error, and upgradeneeded events, but not for the blocked event (MDN). Seems like a candidate for what might be going wrong. Any chance you could try registering a listener and logging if its called?

request.addEventListener('blocked', async () => {
  tbLog('OD: blocked!');
}

Thanks!

@GaurangTandon
Copy link
Author

I added these logs as suggested:

function _openDatabase() {
    tbLog('OD: init');
    const request = indexedDB.open(DB_NAME, DB_VERSION);
    tbLog('OD: requested: ' + request.readyState);
    return new Promise((resolve, reject) => {
        request.addEventListener('blocked', () => {
            tbLog('OD: blocked');
        });
    ...

The logs I get end in the following:

...
[ 1726850923712, IA: 0 ],
[ 1726850923712, OD: init ],
[ 1726850923712, OD: requested: pending ]

The numbers are timestamps, indicating that indexedDB.open() finishes instantly, however, none of the events fire.

The last log timestamp is at 16:48:43.712 UTC, and we wait for 40 seconds (from browser startup) before logging the error. Our error got logged at 16:49:23.354 UTC, indicating that for roughly 40 seconds none of the events had fired. This timing is consistent in all our (five) Sentry error reports so far.

We have errors on Edge 129.0.0 as well as on Chrome 128.0.0. I'm happy to provide more information as needed.

@hsubox76
Copy link
Contributor

The numbers are timestamps, indicating that indexedDB.open() finishes instantly, however, none of the events fire.

indexedDB.open() is async and returns a promise, so it should always continue to the next line. If you want to know if the operation completed, you'll probably have to await it or put your log in a then().

I'm not sure that having you put logs into your app is the most efficient way to debug this. Are you able to create a minimal repro that we can use on our end? Just an app with a single source file that calls onAuthStateChanged and hangs, and has enough webpack config to build, that we can git clone, build, and sideload locally into Chrome to test out? I'm assuming that you can reproduce this error locally if you sideload the extension into Chrome?

@GaurangTandon
Copy link
Author

@hsubox76 Thanks for your response.

If you want to know if the operation completed, you'll probably have to await it or put your log in a then().

Right, of course, I had only added the logs as requested in the previous comment.

I'm assuming that you can reproduce this error locally if you sideload the extension into Chrome?

I am not able to reproduce this locally. I could send you a minimal version of our app with just the Firebase calls, but I'm not sure if it would actually reproduce the problem (because I have no way to verify).

On our Chrome extension with around 2000 users, the issue has happened ~61 times in the past seven days. So we're able to get new logs fairly quickly as needed.

@hsubox76
Copy link
Contributor

I am not able to reproduce this locally. I could send you a minimal version of our app with just the Firebase calls, but I'm not sure if it would actually reproduce the problem (because I have no way to verify).

On our Chrome extension with around 2000 users, the issue has happened ~61 times in the past seven days. So we're able to get new logs fairly quickly as needed.

This is pretty important information. The initial report seemed to give the impression this always happened. Do you have any data on any commonalities between the cases where this happens? Is it on a specific OS, or a particular version of Chrome, at a particular time of day, from a particular region? Is there any way to tell if the users have privacy settings set or are using other ad-blocking or privacy extensions?

I would like to know if you see the same errors if you don't use IndexedDB persistence, but since you're gathering this data from production, that would require changing the functionality of your production app drastically so you probably can't do that.

@GaurangTandon
Copy link
Author

We've observed that the issue occurs across various browsers (Chrome 127/128/129, Edge 129/130), operating systems (Windows/macOS/Linux), and at all times of the day. We've noticed that the distribution of affected browsers, OS, and timezones correlates closely with our user base - none of these parameters differ from the usual.

I'm afraid we don't have any information on the region, and we're unable to determine what other Chrome extensions the user might have. Could you please let us know which privacy settings you'd be most interested in checking?

You're quite right that we cannot switch off IndexedDB persistence in our production extension at this point.

Thanks once again for your continued investigation on this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants