Firestore is not picking up fresh auth token and reinitialising event listeners when the current token is stale.

[russellwheatley]

[READ] Step 1: Are you in the right place?

Issues filed here should be about bugs in the code in this repository. If you have a general question, need help debugging, or fall into some other category use one of these other channels:

• For general technical questions, post a question on StackOverflow with the firebase tag.
• For general Firebase discussion, use the firebase-talk google group.
• For help troubleshooting your application that does not fall under one of the above categories, reach out to the personalized Firebase support channel.

[REQUIRED] Step 2: Describe your environment

• Android Studio version: Android Studio Flamingo | 2022.2.1 Patch 2
• Firebase Component: _____ Firestore, Auth
• Component version: Android BOM 32.0.0

[REQUIRED] Step 3: Describe the problem

We have this issue on the FlutterFire repository: https://github.com/firebase/flutterfire/issues/11146 There's also an active SO issue here: https://stackoverflow.com/questions/76436462/firebase-logged-in-user-with-expired-auth-id-token?noredirect=1

To summarise:

1. The user logs in via Auth SDK. Firestore snapshot event listeners are attached.
2. The app goes into the background for a lengthy period of time (in the range of 5-10 hours).
3. Whilst the user is still logged in, the event listeners start firing exceptions with "permission-denied" exceptions.
4. Requires manually reattaching the Firestore snapshot listeners to make use of the fresh auth token.

My understanding and after discussion with @puf, Firestore ought to pick up the fresh auth token under the hood, and reattach the snapshot event listeners without the user having to do this step manually.

Steps to reproduce:

Not an easy one to reproduce as it requires a lengthy time period, but following on from the summary:

1. Implement Firestore event listener that requires level of auth access via Firestore rules.
2. Log user in via Auth with access to the data being listened to.
3. Put app in background for >= 10 hours (Might be worth just letting it run for the day and coming back to it.)
4. Bring app to foreground, add data to that aspect of data being listened to on snapshot listener, and wait for a permission-denied error via logcat.

The user mentioned in the FlutterFire issue that the problem occurs when the app is brought to the foreground but I have asked for confirmation whether it occurs when the app is also in a background state as I suspect it does. This would remove the variable of app state from the reproduction.

Relevant Code:

Create a barebones app on android studio and implement simple Auth login with Firestore event listener following steps mentioned above.

[MarkDuckworth]

@russellwheatley, I'll work on a reproduction and see if we can get this fixed.

[ramsayamarin]

@russellwheatley @MarkDuckworth The initial problem I faced was that after resuming the app after an extended period (a day or two), all long-lived snapshots would stop updating, even though new reads and writes would still go through. I managed to apply a temporary patch to the issue by recreating all snapshot listeners when the app resumes. The following is an example of how this was done:

  @override
  void didChangeAppLifecycleState(AppLifecycleState state) {
    if (state == AppLifecycleState.resumed) {
      _attachListener();
    }
  }

  void _attachListener() {
    _hangoutSubscription?.cancel();
    _hangoutSubscription = FirebaseFirestore.instance
        .collection(FirePath.hangouts)
        .where....
        .snapshots(includeMetadataChanges: true)
        .transform(ignorePermissionDeniedTransformer())
        .listen((snapshot) {
          ...
        }, onError: (error) {
          FirebaseCrashlytics.instance.recordError(
            error,
            StackTrace.current,
            reason: 'Error in AdminHangoutRepository',
          );
        });
  }
}

This solution seemed to fix the issue in production for a few days, but today a new variant of the problem appeared. This time, the issue seems to be that the token didn't refresh, and yet the user remained logged in. I have this code in place to log out the user, but it didn't trigger:

_authStateSubscription =
    FirebaseAuth.instance.authStateChanges().listen((user) {
  if (user == null) {
    set(RouteState.login()); //did not fire when auth id token expired
  }
});

As shown in this video I captured from my production app today, nothing updates in response to my read and write requests. Connecting my phone to logcat indeed showed permission errors:

 16:29:15.551 19076 Firestore        com.letshang.app        W  (24.6.0) [z0]: (74f4cfa) Stream closed with status: j1{code=PERMISSION_DENIED, description=Missing or insufficient permissions., cause=null}.
16:29:15.564 19076 Firestore        com.letshang.app        W  (24.6.0) [Firestore]: Write failed at users_private/JDGWvPLVtNTcrb: j1{code=PERMISSION_DENIED, description=Missing or insufficient permissions., cause=null}
16:46:09.985 19076 Firestore        com.letshang.app        W  (24.6.0) [Firestore]: Listen for Query(target=Query(hangouts where statein[pre_open,open] order by geohash_6, __name__);limitType=LIMIT_TO_FIRST) failed: j1{code=PERMISSION_DENIED, description=Missing or insufficient permissions., cause=null}

Despite these permission errors, the user remains logged in and authStateChanges doesn't get called. I'm currently unsure how to patch this until Firebase addresses this fundamental issue. A potential workaround could be calling user.getIdTokenResult() on each app resume, or perhaps performing a single write every few hours on app resume to check for the permission denied error, and then automatically log out the user if it's encountered.

Please let me know if there are any potential issues with my approach to detecting when the user should be logged out, or if you have found a more effective temporary workaround for this issue.

[puf]

Thanks for the additional info @RamsayGit. Most helpful, and appreciated. 🙏

A potential workaround could be calling user.getIdTokenResult() on each app resume

My fear is that your getIdTokenResult will only happen after the connections to Firestore are already restored - and thus the listeners cancelled due to not meeting the requirement of the rules. So the full workaround would then require you to also re-attach the listeners. Totally fine for a workaround, but I hope Mark can reproduce the issue and find the root cause.

[ramsayamarin]

In my most recent Android app release, I've introduced code that detects the 'Permission Denied' error upon app resume and prompts the user to re-login to rectify the situation. While this solution initially seemed effective, I discovered it does not work consistently; completely restarting the app proves to be a more reliable solution.

To summarize the various instances in which this error occurs:

1. The issue appears to be exclusive to Android.
2. Implementing token refresh and recreating snapshot listeners on app resume has alleviated the severity of the error, yet it persists.
3. On occasions when solution number 2 fails, the token is invalidated across the entire app. Re-logging in only occasionally resolves this; more often, a complete app restart is necessary. Notably, Firebase maintains the user login throughout these episodes.
4. This is a significant, foundational bug that effectively incapacitates Firebase for Flutter on Android. I would strongly recommend Google to halt further Firebase development and concentrate on rectifying this core issue. This affects every user of Firebase and Flutter on Android.

Here's a video demonstrating the error occurring twice recently, where the only effective solution was to restart the app.

[MarkDuckworth]

I attempted to reproduce this week with my own app, but did not have success. I'm tweaking some things and continuing to try.

Can you tell me if this is only happening on a specific device or is this happening for many users of your app? Have you seen the issue on an emulator?

Despite these permission errors, the user remains logged in and authStateChanges doesn't get called.

I'm curious if idTokenChanges would trigger for this event. Have you tried using this?

On occasions when solution number 2 fails, the token is invalidated across the entire app. Re-logging in only occasionally resolves this; more often, a complete app restart is necessary. Notably, Firebase maintains the user login throughout these episodes.

Can you tell me more about this? How are you implementing this re-logging in? Can you go into more detail about "Firebase maintains the user login throughout these episodes"? Are other Firebase services also affected in this scenario?

Would you be willing to share more context from the Firestore SDK logs? Specifically include in the logs from the time period when the app fails to refresh the token, or when you believe that happens. If you want to share those logs securely, you can create a support case, where you can reference this ticket and share logs.

I'm not available to work on this issue next week but will pick it up after. CC'ing @prameshj and @ehsannas for visibility.

[ramsayamarin]

I attempted to reproduce this week with my own app, but did not have success. I'm tweaking some things and continuing to try.

To reproduce this issue, imagine an app with two pages: a login page and a time display page. Users should be able to log in using Google, then navigate to the time display page. On this page, a snapshot listener should be set up to monitor updates to a Firestore document, which contains a time field updated every minute by a server cloud function, and is guarded by security rules (request.auth != null) that require user authentication for access.

The key detail here is the snapshot listener: it should be initialized only once when the user logs in and should continue to listen for updates throughout the entire duration of the app's lifecycle, which could span multiple days. It's crucial not to recreate the snapshot listener or restart the app during this period.

The app should also listen for null Firebase auth user events to automatically redirect to the login page when a user logs out. After building the app into a release APK and installing it on a phone, the issue can be reproduced by repeatedly bringing the app from the background state to the foreground every few hours to verify if the time displayed updates on app resume. Generally, within a day or two, you should encounter the issue when you notice the time no longer updates on app resume, yet the user remains logged in (the user remains in the time display page).

Can you tell me if this is only happening on a specific device or is this happening for many users of your app? Have you seen the issue on an emulator?

This problem isn't limited to a specific Android device. According to Crashlytics data, it happens across various Android devices. This issue hasn't been reported on iOS. Also, it doesn't appear on emulators or in regular debug builds. It manifests primarily in production on actual Android devices where the app can remain in the background for extended periods and is occasionally brought to the foreground, mirroring typical user behavior. Importantly, Flutter's tendency to fully restart the app upon resuming in debug builds likely obscured this problem during development.

I'm curious if idTokenChanges would trigger for this event. Have you tried using this?

Regarding the use of idTokenChanges, this approach was not adopted because at the time of implementation, it seemed more straightforward to monitor user auth events to ascertain if a user is logged in or not.

Can you tell me more about this?

There is 2 variants of this problem: 1- The snapshot listener ceases to receive updates, resulting in stale data, without producing any errors. I believe I've managed to resolve this by refreshing the token when the app resumes and then re-creating all long lived snapshot listeners. This allows the app to function normally. 2- Sometimes, upon re-creating the listeners, I encounter a 'permission denied' exception. This affects all operations across the app, effectively crippling its functionality. Despite this, the user stays logged in (Firebase user auth is not null). In these instances, I advise the user to attempt re-logging in or to restart the app if the problem persists, as illustrated in this video.

How are you implementing this re-logging in?

When the app detects an error, a prompt notifies the user and guides them to manually log out and log back in. This sequence is depicted in the video. Logging out is accomplished with a simple call to FirebaseAuth.instance.signOut() and my router automatically sends the user back to the login screen. Although this usually works, it does not always rectify the problem, as the video demonstrates. In such cases, restarting the app is the most reliable solution.

Can you go into more detail about "Firebase maintains the user login throughout these episodes"?

When I say "Firebase maintains the user login throughout these episodes," I mean that at no point is the user automatically logged out. Despite the token seemingly being invalid—as evidenced by the snapshot listeners throwing 'permission denied' errors—the user stays logged in, as demonstrated in the video. The Firebase logout detection code never activates:

    _authStateSubscription =
        FirebaseAuth.instance.authStateChanges().listen((user) {
      if (user == null) {
        set(RouteState.login());
      }
    });

Are other Firebase services also affected in this scenario?

I can't confirm whether they are affected, as Firestore is used in 99% of the operations within my app.

Would you be willing to share more context from the Firestore SDK logs?

The logs predominantly contain 'permission denied' errors without further significant information. Here's an instance from Crashlytics:

Non-fatal Exception: io.flutter.plugins.firebase.crashlytics.FlutterError: [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation.
       at StandardMethodCodec.decodeEnvelope(message_codecs.dart:652)
       at MethodChannel._invokeMethod(platform_channel.dart:310)
       at MethodChannelDocumentReference.set(method_channel_document_reference.dart:32)

[MarkDuckworth]

I attempted to reproduce again this week, this time with a release build of my app. The app has been running most of the week and I have not been able to reproduce the issue. Testing included letting the app run in the background overnight several times, running the app in the bg and opening it every few hours through the day. I also tested changing networks during the bg period and leaving the phone offline for multiple hours.

@russellwheatley, did you reproduce the issue as well? Have either of you reproduced with the firebase-android-sdk or only with the Flutter SDK in a Flutter app? If so, can you provide that reproduction?

For what it's worth, we did some analysis to see if there is a higher rate of PERMISSION_DENIED or UNAUTHORIZED errors from the Android clients. This would indicate that there is a token refresh issue for the Android SDK affecting many apps. We did not see evidence of that in our analysis.

[ramsayamarin]

I will start working on a reproduction this week. In my live app I had to resort to measures such as extending the token lifetime significantly alongside code hacks I already implemented such as recreating all snapshots on app resume and still it remains by far the most reported error in Crashlytics in Android and to a lesser extent iOS.

Note these would be 10x worse if I kept the token refresh at 1 hour.

[russellwheatley]

Thanks for the investigation, @MarkDuckworth. I have not recreated this issue. Happy to investigate the reproduction @RamsayGit creates 👍

[ramsayamarin]

@russellwheatley @puf @MarkDuckworth Here it is:

I've created a Minimal, Complete, and Verifiable Example (MCVE), and within four hours of launching the app (in release mode with Play Integrity App Check APK on device), the snapshot listener ceased functioning due to a permission error, as shown. It's no longer tracking the cloud-updated time value and the user remains logged in.

The MCVE contains several API keys, and the project is associated with a paid Blaze plan, as cloud functions weren't compatible with the Spark plan. Could you please guide me on securely sharing this project and the APK with you, and suggest measures to ensure I don't incur charges for this project? I have a 40mb full project folder zip and the 20mb APK I installed on my device to reproduce the error.

[MarkDuckworth]

That's great news! Can you share the source as a github repo and remove your keys? A private repo works. I can configure it to run against one of our test projects.

[ramsayamarin]

I've created a repo and sent you an invitation. A significant part of the setup needed to recreate the error resides within the Firebase project, not the code. I will highlight the most crucial elements:

1- App Check must be enforced for Firestore with Play Integrity, and the token refresh set to the minimum of 30 minutes. 2- Google Sign-In needs to be enabled. 3- The Firestore security rules should be set up as follows:

rules_version = '2';

service cloud.firestore {
  match /databases/{database}/documents {
    match /{document=**} {
      allow list: if request.auth != null 
      	&& request.auth.token.firebase.sign_in_provider == 'google.com'
        && request.query.limit <= 5;
    }
  }
}

4- The Storage security rules should be set up as follows:

rules_version = '2';

service firebase.storage {
  match /b/{bucket}/o {
    match /{allPaths=**} {
      allow read, write: if request.auth != null;
    }
  }
}

5- Firestore should be set up as displayed in the image:

6- Deploy the cloud function that continuously updates the time field. 7- Build the app into a release APK, deploy it to a physical device, and periodically resume it from the background.

[MarkDuckworth]

I didn't realize this involves App Check. When you say, "App Check must be enforced for Firestore with Play Integrity", does that mean you only see this when using app check?

[ramsayamarin]

I didn't realize this involves App Check. When you say, "App Check must be enforced for Firestore with Play Integrity", does that mean you only see this when using app check?

I never tried without App Check so I cannot comment on that. This is a stripped down version of my actual released project in terms of Firebase setup. I didn't ever think of not enabling app check since it felt like a necessary security measure.

[ramsayamarin]

@MarkDuckworth Can I please be informed of the current status of this bug?

[MarkDuckworth]

Hi @RamsayGit, once I added App Check to my own Android app built with the Firebase Android SDK, I started producing a similar behavior, though in my case logging in again seemed to solve the problem consistently. I do believe this is related to app check, and I have shared it with that team. However I do intend to take another look in the next week to see if I can move it forward.

Not sure if it will be useful to you at this point, but there is an API to listen for AppCheck token state changes.

[ramsayamarin]

@MarkDuckworth After further testing with the MCVE project I'm almost certain the issue is directly related to Appcheck since I could not replicate the error with Appcheck turned off. When do you anticipate this issue to be resolved? it remains the most reported bug affecting users daily and I'm wondering if it is acceptable to turn Appcheck off and rely on security rules alone?

[MarkDuckworth]

@RamsayGit can you share your Flutter MCVE with me again, I lost access to the repo?

I spent some time digging into this issue again this week and what I was seeing in my Android Java app may have been a red herring. I was experiencing my activity being destroyed and re-created after being in the background for a while. After re-creation the listeners were not correctly restarted. It's unclear why I initially started seeing that when I enabled app check.

Regardless, based on the described behavior and what you tested above, I still feel that this is related to app check. It may also be specific to Flutter and the Flutter lifecycle. I'm not a Flutter dev, so I could use some help from @russellwheatley.

I'm wondering if it is acceptable to turn Appcheck off and rely on security rules alone?

I think that's a question only your team can answer.

Additional thoughts:

• When reviewing the app check token logic in Android Firebase, failure to refresh should be logged. Do you see any error messages like "Firebase AppCheck API not available" or "Failed to get AppCheck token"?
• Regarding a workaround. When you detect this scenario, have you considered using the getToken method to force and app check token refresh?

[ramsayamarin]

@MarkDuckworth I did not see any error messages regarding this issue other than the 'caller does not have permission...' error. I did implement many workarounds to help mitigate this issue including calling user.getIdTokenResult() on each app resume which would refresh the token if it is expired, however this does not eliminate the issue, just decreases its incidence by a bit but it remains the biggest issue in my app and that is visible in my crashlytics. The issue is certainly related to app check, I can only comment on my the MCVE I provided since all my apps are in flutter. You are already added as a collaborator in the repo, are you sure you don't have access? I also have a ready flutter project with API keys setup and ready to go alongside a ready to install APK so you can just install and check on you device. I can share these with you directly if you want.

[MarkDuckworth]

@russellwheatley, We've reviewed this and can't find a repro on native Android. I've chatted with several adjacent teams from Firebase Android and App Check, and it seems like the next step is to see if you can get any additional information from the customer's FlutterFire MCVE. Can you test the MCVE and see if you can provide the full Firebase log output from the app? Also, the AppCheck team wanted to ensure that the issue occurs when Auth is disabled and AppCheck is enabled, is that something you can test?

[google-oss-bot]

Hey @russellwheatley. 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!

[russellwheatley]

Hey @MarkDuckworth, sorry for late response. I can take a look at the FlutterFire MCVE and see what I find 👍

[russellwheatley]

@RamsayGit - my invitation to the repo has expired, do you mind reinviting me, please?

[ramsayamarin]

@RamsayGit - my invitation to the repo has expired, do you mind reinviting me, please?

@russellwheatley Invitation has been sent.

[gmarizy]

I experience the same error, on Android and iOS alike, and I use app check too.

This error might be related: https://github.com/firebase/flutterfire/issues/11491

In our app, we display a retry button when Firestore snapshot stream fail. Some people reported to me that when the problem occur, they must press the retry button several times before having data. My uneducated guess is that app check token renew might fail (see linked issue) or be too slow, triggering a timeout in Firestore client or something like that.

[ramsayamarin]

@gmarizy @russellwheatley Yes the bug is due to App Check and the only way I could get rid of it is by disabling App Check. I submitted a reproduction to the Firebase team 2 months ago and I'm awaiting an update from them.

[russellwheatley]

@RamsayGit - as a small update, I have the app running since yesterday on my android device with App Check enforced. No error as yet. I will keep it running until over the next few days in the hope I see the error.

I am curious about the Storage rules. There isn't any Storage plugin usage, and I presume you use Storage as part of your app and not part of the MCVE.

[gmarizy]

Mine:

rules_version = '2';
service firebase.storage {
  match /b/{bucket}/o {
    match /{allPaths=**} {
      allow write: if request.auth != null;
      allow read: if true;
    }
  }
}

And I don't enforce App Check for storage.

[gmarizy]

I just noticed that I have some "Unverified requests" on App Check reports concerning Firestore. App check is enforced for Firestore, so I guess those unverified request correspond to the [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. errors.

Just a wild guess: when app is in background, under unknown circumstances App Check token is not renewed. When app is resumed, active snapshots listening trigger calls to Firestore but without App Check token attached, since there is no valid one available.

[russellwheatley]

I just noticed that I have some "Unverified requests" on App Check reports concerning Firestore. App check is enforced for Firestore, so I guess those unverified request correspond to the [cloud_firestore/permission-denied] The caller does not have permission to execute the specified operation. errors.

FYI; I have observed unverified requests without triggering the "permission denied" exception.

Just a wild guess: when app is in background, under unknown circumstances App Check token is not renewed. When app is resumed, active snapshots listening trigger calls to Firestore but without App Check token attached, since there is no valid one available.

This seems likely to me. A permission denied response seems to be a result of a stale token. Particularly as @RamsayGit mentioned this does not occur once App Check is deactivated.