firebase / firebase-ios-sdk

Firebase SDK for Apple App Development
https://firebase.google.com
Apache License 2.0
5.67k stars 1.49k forks source link

Firebase ID token has expired. #6521

Closed IgorRosocha closed 2 years ago

IgorRosocha commented 4 years ago

[REQUIRED] Step 1: Describe your environment

[REQUIRED] Step 2: Describe the problem

Steps to reproduce:

In our app, we use Firebase authentication token to identify user on our backend. We are sending this token with every request. We retrieve Firebase token using getIDToken(completion:) with every request.

The documentation says the method Retrieves the Firebase authentication token, possibly refreshing it if it has expired., but from time to time, we receive error Firebase ID token has expired. Get a fresh ID token from your client app and try again (auth/id-token-expired). See https://firebase.google.com/docs/auth/admin/verify-id-tokens for details on how to retrieve an ID token. This is kind of a major issue for our app, as we automatically log out users which receive unauthenticated error (because of user deletion functionality) - not mentioning that all of the requests automatically fail because of expired token.

Am I misunderstanding the concept of retrieving the token using getIDToken(completion:), or is this the bug in SDK?

sam-gc commented 4 years ago

Hi, thanks for reaching out--

Where are you seeing the auth/id-token-expired error? In your backend code or on the client?

How much time elapses between calling getIdToken and your backend doing the verification? Is it possible the token is becoming expired in flight (meaning: order of minutes between getting it from the client and doing verification on the backend)

IgorRosocha commented 4 years ago

Where are you seeing the auth/id-token-expired error? In your backend code or on the client?

In the response from backend.

How much time elapses between calling getIdToken and your backend doing the verification? Is it possible the token is becoming expired in flight (meaning: order of minutes between getting it from the client and doing verification on the backend)

I believe not. This happens after user launches the app, and sends initial requests with token to BE. Token is retrieved on the client using getIDToken(completion:) with every request.

sam-gc commented 4 years ago

Hmm yeah this is interesting. The relevant bit of code is here: https://github.com/firebase/firebase-ios-sdk/blob/master/FirebaseAuth/Sources/SystemService/FIRSecureTokenService.m#L110

The token should be valid for at least 5 minutes whenever you call this. Is there any more detail in the error you get back from the server? (A code or anything of that sort?)

IgorRosocha commented 4 years ago

Is there any more detail in the error you get back from the server? (A code or anything of that sort?)

Not really. We use gRPC, and the response received from BE looks like this:

failure(unauthenticated (16): Firebase ID token has expired. Get a fresh ID token from your client app and try again (auth/id-token-expired). See https://firebase.google.com/docs/auth/admin/verify-id-tokens for details on how to retrieve an ID token.)

Metadata received from BE contain this mesage:

Firebase ID token has expired. Get a fresh ID token from your client app and try again (auth/id-token-expired).

olejnjak commented 4 years ago

Would it be possible that if multiple calls to getIDToken(completion:) are made, we would receive one valid token for the first time, which will be invalidated with subsequent calls?

EDIT: But as I look into how FIRSecureTokenService works, it seem to be unlikely.

sam-gc commented 4 years ago

Chatted with the team a bit-- one thing to consider is that the SDK will automatically refresh the token if it has expired or if it will expire in the next 5 minutes. If the device has its clock running a bit behind then it will think the token has not expired even though it may have. Then, when you send it to your backend, your backend has the correct time and sees the token as expired.

The reverse may be true as well: if for some reason your server's clock is a bit ahead, it may incorrectly think the token is expired.

One thing to try: you can manually parse the ID token and log failures. Here's a snippet in Javascript but you can apply this equally in any language:

// Where atob is Base64 decode
const expirationTimeInSecondsSinceEpoch =
    JSON.parse(atob(token.split('.')[1])).exp

That will get you the expiration time of the token in question. I'd suggest adding some sort of logging to your backend that records the token's expiration time and the server's current time when you catch this particular error.

(And I have to post this just in case, please don't post the ID token or other information here :smile: )

google-oss-bot commented 4 years ago

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

olejnjak commented 4 years ago

We are currently deploying solution that will incorporate such logging as mentioned by @samhorlbeck.

pixelmatrix commented 4 years ago

My team has been seeing the same issue intermittently for a while. After reviewing the source of this library, and the admin-sdk, my suspicion is that the client thinks an expired token is still valid when it is not. In our case, it seems to happen more frequently for requests made right after the app is foregrounded.

I noticed that FIRSecureTokenService caches an estimated expiration date for the token, and uses that to determine whether it's expired, rather than decoding and inspecting exp field of the actual token. Perhaps that could be where the issue is happening?

As a mitigation strategy we implemented a retry that will force refresh the token manually and resubmit the request if we receive a response that indicates an invalid token. That being said it would be great to get to the bottom of this issue.

pixelmatrix commented 4 years ago

To help figure out what's going on, I've added some validation on the client to check the token every time before it's submitted to the server. Over the weekend I was able to get a couple repros, showing that the ID token provided from auth sdk was actually expired.

An excerpt from the logs:

UserInfo={
expiredAt=2020-10-12 00:27:04 +0000, 
NSLocalizedDescription=Expired token received from FIRAuth, 
currentTime=2020-10-12 00:53:41 +0000
}

UserInfo={
expiredAt=2020-10-11 00:45:30 +0000, 
currentTime=2020-10-11 00:55:16 +0000, 
NSLocalizedDescription=Expired token received from FIRAuth
}
pixelmatrix commented 4 years ago

To get a token, I'm calling Auth.auth().currentUser.getIDToken(completion:). To verify the token locally, I followed the same path that the backend uses (firebase-admin-sdk via jsonwebtoken npm package).

1) Split the JWT into it's various parts 2) Find the payload part 3) base64 decode it 4) Parse it into JSON 5) Extract the value from the "exp" key as a number 6) Compare current date's timeIntervalSince1970 with expires at date

    func verifyIDToken(token: String) throws -> Bool {
        let parts = token.split(separator: ".")
        // JSON Web Token should have a header, payload, and signature
        guard parts.count == 3 else {
            throw NSError(domain: "com.glasswing.cocoon", code: 500, userInfo: [
                NSLocalizedDescriptionKey: "Token has wrong number of parts. Expected 3, got \(parts.count)"
            ])
        }
        var payload = String(parts[1])
        // Base64 strings need to be divisible by 4 to be decoded with Data, otherwise pad with '='
        // https://stackoverflow.com/questions/4080988/why-does-base64-encoding-require-padding-if-the-input-length-is-not-divisible-by
        while payload.utf8.count % 4 != 0 {
            payload.append("=")
        }
        // Payload is base64 encoded json
        guard let payloadData = Data(base64Encoded: payload, options: .ignoreUnknownCharacters) else {
            throw NSError(domain: "com.glasswing.cocoon", code: 500, userInfo: [
                NSLocalizedDescriptionKey: "Token payload could not be decoded from base64 to json string"
            ])
        }
        guard let parsed = try? JSONSerialization.jsonObject(with: payloadData, options: []) as? [String: Any] else {
            throw NSError(domain: "com.glasswing.cocoon", code: 500, userInfo: [
                NSLocalizedDescriptionKey: "Token payload json could not be parsed"
            ])
        }
        // Expiration date is "exp" field
        guard let exp = parsed["exp"] as? Int else {
            throw NSError(domain: "com.glasswing.cocoon", code: 500, userInfo: [
                NSLocalizedDescriptionKey: "Could not find value for `exp` key in token payload"
            ])
        }
        let isExpired = Date().timeIntervalSince1970 >= TimeInterval(exp)
        if isExpired {
            // Log an error to Sentry to track instances of this
            let error = NSError(domain: "com.glasswing.cocoon", code: 500, userInfo: [
                NSLocalizedDescriptionKey: "Expired token received from FIRAuth",
                "expiredAt": Date(timeIntervalSince1970: TimeInterval(exp)),
                "currentTime": Date()
            ])
            AnalyticsManager.shared.trackError(error: error)
        }
        return !isExpired
    }
pixelmatrix commented 4 years ago

Just a small update on these logs I've been collecting. The build that has this logging is now out in prod, and we've seen 6.5k instances of this across 1.5k unique users over the last week. Let me know if there's other details I can add to the logs to help debug.

garysmckiernan commented 3 years ago

I'm also seeing this issue.

Xcode version: 12.2 Firebase SDK version: 7.00.0 Firebase Component: Auth Component version: 7.00.0 Installation method: Cocoapods

As described above the function getIDToken(completion:) is returning an expired token. We've also tried getIDTokenForcingRefresh(_:completion:) with force refresh set to true and we are still getting expired tokens from this call.

As a work around we are now forcing refresh & retrying on every request to try and ensure the user gets a valid token.

sdgroot commented 3 years ago

Xcode version: 12.3 Firebase SDK version: 6.32.2 Firebase Component: Auth Component version: 6.32.2 Installation method: Cocoapods

We're seeing the same issue unfortunately. We get the token using getIDToken(completion:) right before each request, and on the server we get an expired token error, using the Firebase Admin SDK. This has happened 800 times for about 700 users in the past week.

Strange thing is though, that it doesn't always return an expired token. I've done some manual testing on both a real device and the sim, using different identity providers, and found that I always got back a valid refreshed token after waiting for an hour.

rosalyntan commented 3 years ago

Hi folks, thanks for the additional info! About what percentage of users and requests are you seeing this with? Unfortunately, I've not been able to reproduce this in my own manual testing, and it would be helpful to know the frequency of this issue.

pixelmatrix commented 3 years ago

@rosalyntan It's hard to get an exact % for you due to how our error logging is performed, but it appears to be intermittently affecting nearly all active users of our app since we added this logging.

My suspicion is that it has something to do with the app lifecycle. We make network requests that rely on this token as the app is transitioning into the background and also as it transitions into the foreground. We use background tasks paired with our network requests to request extra time as the app makes this transition to ensure the network request is successful. It appears that the requests that are being made with an expired token are typically one of the first network requests after a background -> foreground transition.

I have repro'ed this issue several times on my own device, but since it relies on time constraints I typically have to install a build and use it intermittently over the course of a day, and review the logs later. Let me know if I can add more details to my own logging that could help here.

gilbertl commented 3 years ago

We're facing a similar issue on our application.

Can we get an update here? It's happening to ~1% of our requests every week, but our app fails hard when it happens. It's not clear how we're suppose to recover from 401s.

Looking at the above messages, it's been 4 months since the issue was first reported. Is this being prioritized?

@rosalyntan

gilbertl commented 3 years ago

Is there a workaround for now?

For example, would it be advisable to force refresh tokens every X minutes?

pixelmatrix commented 3 years ago

@gilbertl It may not be ideal, but what we do is verify the token locally (using the code I shared above) to make sure it's not expired before submitting each request. If it's expired we automatically request a new token forcing refresh before using the token.

IgorRosocha commented 3 years ago

Is there a workaround for now? For example, would it be advisable to force refresh tokens every X minutes?

@gilbertl the workaround we have implemented for now looks like this -> if any request fails because of expired token, we force token refresh using getIDTokenForcingRefresh(true) and then retry request using freshly retrieved token

I wouldn't advise to force refresh token regularly, as it may cause unnecessary overhead and not ensure 100% reliability.

sdgroot commented 3 years ago

For us, it looks to be about 6-7% of our daily userbase that are impacted by this issue.

Some background info that may be of help: we have an app that sends the user a notification once every day, at a random time. This notification is the trigger for a user to take a picture of what they're doing at that very moment. Because of this, most users use the app only for a short duration, once every day. We do get a lot of complaints that as soon as they open the app by tapping the notification, they're signed out. To some, this happens every single day. This is triggered by a 401 response from our backend that encounters a 'token expired' exception when validating the token with the Firebase Admin SDK.

We've implemented the same workaround for now, where we trigger a force refresh of the token when we encounter a 401 server response, and then retry the request with the new token.

hognevevle commented 3 years ago

I'm experiencing this same issue with the javascript SDK. In my SPA, I can reliably reproduce this in the following manner:

1) Authenticate via Firebase, everything will work normally 2) Leave the computer for a while (Mac in my case), so that it goes into Sleep mode (or manually put it into Sleep I guess). Let it sleep for a while (an hour or so, so that the last retrieved token will have expired) 3) Wake up the computer, and resume using the app. For some reason, firebase.auth().currentUser.getIdToken() will now still continue to serve the previous token, which has now expired.

I realize this isn't related to the iOS SDK specifically, but I wanted to chime in, in case the issue isn't unique to this specific SDK.

rosalyntan commented 3 years ago

Hi folks -- the additional logging added in #7461 should be in the upcoming release.

To turn on debug logs:

  1. In Xcode, select Product > Scheme > Edit scheme.
  2. Select Run from the left menu, then select the Arguments tab.
  3. In the Arguments Passed on Launch section, add -FIRDebugEnabled.

If you can share the debug logs from whenever you see this issue occur, that would be helpful! I'm looking for logs with the tag I-AUT000017.

@hognevevle Thanks for reporting this! If you haven't already, can you file a separate issue in firebase-js-sdk?

olejnjak commented 3 years ago

Hi @rosalyntan, additional logging is great but I am not sure if this method is the one to take. Not sure that this issue is easily reproducible in debug environment 😬

kanottonp commented 3 years ago

Hi everyone -- I am experiencing the same problem in my application. It can't be reproduced obviously but I'm trying to log as many as possible

Usually, this bug occurred after the function "getIDTokenForcingRefresh" with forceRefresh=false was called just before app became inactive (switch app or return to home). From the log we have, it shows that "getIDTokenForcingRefresh" was called before app went inactive, and callback function was called after app became active a few hours later, with expired token (the same token that being used before app went inactive).

Hope this information could help you guys fix this problem.

weixifan commented 3 years ago

For internal reference: issue b/179436144 tracks this.

michaelhayman commented 3 years ago

Also seeing this issue in the JS SDK about 20 times a day.

jdboris commented 3 years ago

This happens to me every time I run my app after an hour of inactivity

icedice commented 2 years ago

We are seeing this too. Not sure why this is not getting more attention.

sam-gc commented 2 years ago

For the folks seeing this in the JS SDK, please file a separate issue in the JS SDK repo: https://github.com/firebase/firebase-js-sdk/issues

rosalyntan commented 2 years ago

Thank you to everyone who provided information on this issue!

Based on @kanottonp's observations, it appears the issue is caused by the callback being invoked much after the request for the token is made, if the app happens to go into the background before the callback completes. #9253 provides a partial fix that should reduce the occurrences of this issue. However, due to limitations around handling local clock skew, this is not a full fix. If you are still seeing this issue after the fix rolls out, we recommend the workaround mentioned by previous commenters, of catching the token expiry error and calling getIDTokenForcingRefresh(true) before retrying.