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: firebase/flutterfire#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 👍