firebase / firebase-ios-sdk

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

SendVerificationCode method is returning Error Code: 16 in production for some users #12109

Open minlite opened 9 months ago

minlite commented 9 months ago

Description

I'm using Firebase Auth in production. I have Firebase AppCheck enabled and enforced for Authentication.

A small percentage of my users on iOS are seeing the sdk error out with An internal error has occurred, print and inspect the error details for more information. when trying to request a verification code.

I went through our logs in Google Cloud and noticed that the google.cloud.identitytoolkit.v1.AuthenticationService.SendVerificationCode method is failing with error code 16 and message Error code: 16 for them. The logs don't provide any other indication of what error code 16 might be and my search of this error online plus in the firebase emulation tools has not resulted in any answers. Please see the full log with number, ip address, and project details redacted below:

{
  "insertId": "kjdxlhdp2nu",
  "jsonPayload": {
    "status": {
      "code": 16,
      "message": "Error code: 16"
    },
    "request": {
      "phoneNumber": "xxxxxxxxxxxxx",
      "@type": "type.googleapis.com/google.cloud.identitytoolkit.v1.SendVerificationCodeRequest"
    },
    "requestMetadata": {
      "callerIp": "xxxxxxxxxxxx",
      "callerSuppliedUserAgent": "FirebaseAuth.iOS/10.17.0 xxxxxxxxxxxx/7.27 iPhone/16.5.1 hw/iPhone12_3,gzip(gfe),gzip(gfe)"
    },
    "methodName": "google.cloud.identitytoolkit.v1.AuthenticationService.SendVerificationCode",
    "@type": "type.googleapis.com/google.cloud.identitytoolkit.logging.RequestLog",
    "serviceName": "identitytoolkit.googleapis.com"
  },
  "resource": {
    "type": "identitytoolkit_project",
    "labels": {
      "project_id": "xxxxxxxxxxx"
    }
  },
  "timestamp": "2023-11-15T23:25:18.518Z",
  "severity": "ERROR",
  "logName": "projects/xxxxxxxxxxxx/logs/identitytoolkit.googleapis.com%2Frequests",
  "receiveTimestamp": "2023-11-15T23:25:18.876791432Z"
}

As you can see, I am using the latest Firebase iOS SDK (10.17.0) and the user has the latest version of my app.

I doubt this is a clear cut misconfiguration on our side since the majority of users are able to sign in with no issue. I would like if Firebase team can decipher what error code 16 might mean and why the SDK is not providing a more useful error message.

Reproducing the issue

No response

Firebase SDK Version

10.17.0

Xcode Version

15.0

Installation Method

CocoaPods

Firebase Product(s)

App Check, Authentication

Targeted Platforms

iOS

Relevant Log Output

{
  "insertId": "kjdxlhdp2nu",
  "jsonPayload": {
    "status": {
      "code": 16,
      "message": "Error code: 16"
    },
    "request": {
      "phoneNumber": "xxxxxxxxxxxxx",
      "@type": "type.googleapis.com/google.cloud.identitytoolkit.v1.SendVerificationCodeRequest"
    },
    "requestMetadata": {
      "callerIp": "xxxxxxxxxxxx",
      "callerSuppliedUserAgent": "FirebaseAuth.iOS/10.17.0 xxxxxxxxxxxx/7.27 iPhone/16.5.1 hw/iPhone12_3,gzip(gfe),gzip(gfe)"
    },
    "methodName": "google.cloud.identitytoolkit.v1.AuthenticationService.SendVerificationCode",
    "@type": "type.googleapis.com/google.cloud.identitytoolkit.logging.RequestLog",
    "serviceName": "identitytoolkit.googleapis.com"
  },
  "resource": {
    "type": "identitytoolkit_project",
    "labels": {
      "project_id": "xxxxxxxxxxx"
    }
  },
  "timestamp": "2023-11-15T23:25:18.518Z",
  "severity": "ERROR",
  "logName": "projects/xxxxxxxxxxxx/logs/identitytoolkit.googleapis.com%2Frequests",
  "receiveTimestamp": "2023-11-15T23:25:18.876791432Z"
}

If using Swift Package Manager, the project's Package.resolved

Expand Package.resolved snippet
```json Replace this line with the contents of your Package.resolved. ```

If using CocoaPods, the project's Podfile.lock

Expand Podfile.lock snippet
```yml # Uncomment this line to define a global platform for your project # platform :ios, '9.0' # Uncomment this line if you're using Swift use_frameworks! platform :ios, '13.0' target 'XXXXXXXXX' do project 'XXXXXXXXX', 'Debug' => :debug, 'Debug.Staging' => :debug, 'Release' => :release, 'Release.Staging' => :release pod 'FirebaseMessaging' pod 'FirebaseAuth' pod 'FirebaseAnalytics' pod 'FirebaseAppCheck' pod 'FirebaseCrashlytics' pod 'FirebaseRemoteConfig' end ```
google-oss-bot commented 9 months ago

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

morganchen12 commented 9 months ago

When App Check is enabled, error code 16 indicates a request was rejected because the App Check token was missing or invalid. You can view a more granular breakdown of rejected requests in the App Check monitoring graph on Firebase Console. In this case App Check is working as expected and rejecting bad requests.

cc @weixifan, we should probably document this better since there's no online reference materials for this error code.

morganchen12 commented 9 months ago

Closing this issue since it appears to be working as intended, but if you reproduce this error on a device with a valid token, please re-open the issue.

minlite commented 9 months ago

Thank you for the reply @morganchen12!

That was one of my guesses. I checked the monitoring graph and it looks like around 12% of production requests fail due to an invalid AppCheck token. It doesn't seem plausible to me that 12% of my customers are using jailbroken devices or using emulated environments. There has to be an issue with AppCheck token generation in firebase SDK to be causing this high percentage of failures. I expect the natural failure rate to be somewhere close to 1-2%.

I initially thought that https://github.com/firebase/firebase-ios-sdk/pull/11986 could be the culprit (I personally observed this issue on my device), but from my investigation and the log I included, it is clear that the customers are on 10.17.0 (with the fix merged in) and still facing this issue.

I am going to investigate more and try to produce this on a local device or obtain logs from a customer.

morganchen12 commented 9 months ago

@minlite, can you file a support ticket? This way the Firebase team can look at your project directly to see if something's going wrong.

TheHmmka commented 9 months ago

The same situation is here. Part of our audience is failing with Error Code 16...

minlite commented 9 months ago

@minlite, can you file a support ticket? This way the Firebase team can look at your project directly to see if something's going wrong.

I have opened support case 10259958.

swftvsn commented 9 months ago

@minlite Can you inform us here what Firebase support said? We're trying to figure out this exact same thing over here..

minlite commented 9 months ago

@swftvsn Support initially denied that the issue is from Firebase. After I pointed out that 10% of our users as well as users from other production apps are seeing the same issue, they agreed to escalate issue to engineering. No updates after that.

weixifan commented 9 months ago

Thank you for filing this issue.

To clarify, when viewing logs in Cloud Logging, you are looking at the errors experienced by your project's activities in an entire backend. These are not just App Check logs per se. In your case, the backend emitting this log entry is the Firebase Authentication backend, and that backend controls the exact error messages and error codes that are emitted.

I looked into this, and the Firebase Authentication backend uses error codes are the standard codes documented here. Error code 16 is UNAUTHENTICATED and it maps to HTTP 401 Unauthorized.

Because these log entries represent your project's activity in the backend, note that these errors may or may not be caused by App Check. Any call to SendVerificationCode that resulted in UNAUTHENTICATED would be logged in this way, regardless whether App Check was the component rejecting the request or not.

Note also that Firebase Authentication uses its own mandatory layer of abuse prevention (Play Integrity + reCAPTCHA fallback on Android, APNS + reCAPTCHA on iOS) in addition to a layer of optional protection by App Check that you opt into. Without further information from the backend or from the device itself, it's hard to say which component rejected the request here.

Finally, note that it is difficult to perfectly discern the actual false positive rate (that is, the true rate at which genuine clients are labelled as invalid). Were additional signals observed that would indicate that the invalid traffic was in fact legitimate traffic? In other words, how confident are we that these aren't largely from unwanted clients?

One thing you can do is to temporarily unenforce App Check, wait 15 minutes, and afterwards, any UNAUTHENTICATED (error code 16) errors you observe are not caused by App Check.

If after investigating, you have determined that App Check is the one rejecting these requests, the next step would be to investigate why your chosen attestation provider is rejecting your user's devices. It would be especially helpful if you can see the attestation provider error messages logged on-device. Since App Check does not maintain these attestation providers, reaching out directly to their support would be a good idea. However, App Check does maintain the handshake procedures with out-of-the-box-supported attestation providers in the App Check SDK, so if we can provide evidence that it is a problem there, we will definitely take a look.

Hope this helps.

[Edit: oops -- I hit the close issue button by accident. I've reopened.]

minlite commented 9 months ago

Hi @weixifan,

Thank you for the detailed reply and taking the time to look into this issue. I can address a few of the points you brought up:

My investigation of this issue on our platform first began when our support team started getting emails from legitimate users who could not log onto our platform due to seeing "An internal error has occurred, print and inspect the error details for more information." My gut feeling immediately pointed towards an AppCheck issue. Initially I assumed these were requests either from users with older clients before AppCheck support was introduced or from users with tampered with devices, however closer inspection of the users' phone numbers and our logs indicated that they were on the latest version of our app, as well as the Firebase SDK. Additionally, we verified that the users emailing us were legitimate users with stock devices so we are pretty confident that the traffic from these devices should be accepted.

One thing you can do is to temporarily unenforce App Check, wait 15 minutes, and afterwards, any UNAUTHENTICATED (error code 16) errors you observe are not caused by App Check.

I went ahead and disabled App Check enforcement about a week ago, after which all the Error Code: 16 errors from our logs disappeared. This confirmed it is likely an issue with App Check or the Attestation provider.

If after investigating, you have determined that App Check is the one rejecting these requests, the next step would be to investigate why your chosen attestation provider is rejecting your user's devices. It would be especially helpful if you can see the attestation provider error messages logged on-device.

Is there a specific way you would recommend obtaining these logs from our devices of interest? Please let me know if the output of a specific function call would be beneficial to determining the root cause of the issue. Since these deices are all using iOS14+, the provider our app uses is FIRAppAttestProvider.

Thanks!

jostster commented 8 months ago

I just came across this as I was investigating why 4k+ of our users are getting error code 16 on iOS devices. Has there been any follow up?

minlite commented 8 months ago

@jostster I still have App Check disabled since we could not accept losing users on sign up due to this error.

I have continued to investigate this but have found no solution. It is clear though that App Check is the culprit, so it is either a bug from Apple in generating AppAttest tokens or from Google's backend verifying the token. The support case 10259958 is still pending.

I would appreciate it if you could update this issue if you happen to come across more info as far as user segment or commonalities.

jostster commented 8 months ago

And of course Apple and Google will both say "Works on my machine" so it sounds like we are left to either migrate off firebase or find the cause ourselves in the dark. Did you submit an Apple Feedback yet?

jostster commented 8 months ago

Just an FYI from our logs it seems sporadic as some users can login / reset passwords fine, some get an invalid password then error code 16 then a few invalid passwords then an exceeded limit, then a few more error code 16's then some meta data responses for GetAccountInfo then more error code 16's.

minlite commented 8 months ago

And of course Apple and Google will both say "Works on my machine" so it sounds like we are left to either migrate off firebase or find the cause ourselves in the dark. Did you submit an Apple Feedback yet?

If enough people report the same issue here, I hope that we can get Google to take a closer look.

I have not submitted a radar yet since I have not been able to obtain a faulty AppAttest token. If I can do that, then it would probably help in debugging the issue

jostster commented 8 months ago

@weixifan Is it possible this PR is what is causing the issue? I noticed we are both on 10.17.0 and possibly this is causing an unintended side affect with the providers? Unfortunately I cannot reproduce this issue with my accounts so am not able to look at the debug logs.

minlite commented 8 months ago

@jostster I don't think so. I was facing this issue, at a much larger scale, even before 10.17.0. The PR you referenced actually fixed it for most of my users but not all.

jostster commented 8 months ago

Looking through our google cloud logs the error code 16's are mainly from SignInWithPassword method and not the SendVerificationCode method. So it seems this isn't isolated to SMS auth but multiple auth methods.

minlite commented 8 months ago

Do you use Firebase phone auth in your project? This error seems to be mainly caused by a failure in validating the authenticity of the request itself and should be common across all sign in methods.

jostster commented 8 months ago

Do you use Firebase phone auth in your project? This error seems to be mainly caused by a failure in validating the authenticity of the request itself and should be common across all sign in methods.

We do not. We use SignInWithPassword and have MFA available with SMS verification codes but not signInWithPhone. I just posted that showing it doesn't seem to be specific to the SendVerificationCode but AppCheck as a whole.

nohe427 commented 8 months ago

Do you happen to be using ARCore in your apps? We recently fixed an issue in the App Check SDK (v19.1.0) where ARCore was attempting to initialize App check instead of your own project and later passing on invalid tokens

Release notes for 19.1.0

jostster commented 8 months ago

Do you happen to be using ARCore in your apps? We recently fixed an issue in the App Check SDK (v19.1.0) where ARCore was attempting to initialize App check instead of your own project and later passing on invalid tokens

Release notes for 19.1.0

Our project isn't using ARCore.

nohe427 commented 8 months ago

@jostster

Do you happen to be using ARCore in your apps? We recently fixed an issue in the App Check SDK (v19.1.0) where ARCore was attempting to initialize App check instead of your own project and later passing on invalid tokens Release notes for 19.1.0

Our project isn't using ARCore.

This failure isn't limited to ARCore, but can also come from other libraries that use Crashlytics or other firebase features.

Have you ran this on 19.1.0?

Do you happen to have logs from an iOS device that this failed on?

Having the iOS logs from a failing device can give us more information on how to track down the root cause. It should be able to tell us if its an issue with the underlying provider or if the implementation is making a call to the wrong project as we saw with project pre-19.1.0.

minlite commented 8 months ago

@nohe427 Our app also does't use ARCore. However that does raise the question of whether any other framework or library can conflict with AppCheck. Is there a way to check?

nohe427 commented 8 months ago

@minlite - I updated my comment above. It could be that other libraries that use Crashlytics or other firebase features which may cause App check to attempt to initialize with those projects instead of yours.

Having iOS logs from a failing device will help provide some insight into the issue.

jostster commented 8 months ago

@nohe427 I have updated to 10.19.1 and we will release it sometime next week. However, you mentioned that this will fix any other frameworks calling crashlytics, but looking at the PR it looks like it specifically only checks for ARCore which neither of us use.

paulb777 commented 8 months ago

@jostster We have plans to do a more general fix than the specific workaround implemented for ARCore, but haven't yet done so.

Does your app call FirebaseApp.configure() for more than one Firebase App or from any other dependent libraries?

cc: @ncooke3

jostster commented 8 months ago

@jostster We have plans to do a more general fix than the specific workaround implemented for ARCore, but haven't yet done so.

Does your app call FirebaseApp.configure() for more than one Firebase App or from any other dependent libraries?

cc: @ncooke3

Happy new year @paulb777 . I just did a search for FirebaseApp.configure() in our Workspace as well as our dependencies and it looks like aside from our single call in our AppDelegate, only Firebase modules are calling that like FIRMessaging, FirebaseCore, etc. I do also see that GoogleDataTransport seems to have this included as well.

paulb777 commented 8 months ago

Happy New Year @jostster. If that's the case, you're likely seeing a different issue than the one fixed in 10.19.1 and we'll likely need logs to make progress on diagnosis. https://stackoverflow.com/a/55356756/556617

jostster commented 8 months ago

Happy New Year @jostster. If that's the case, you're likely seeing a different issue than the one fixed in 10.19.1 and we'll likely need logs to make progress on diagnosis. https://stackoverflow.com/a/55356756/556617

Unfortunately our engineers are unable to replicate this, but will keep an eye out for if we are we will capture logs.

fmoura-ehab commented 3 months ago

Hey folks. Has anyone ever got to the bottom of this? We're facing the same problem, even the exact same 12% of requests failing.

minlite commented 3 months ago

@fmoura-ehab We did not, and unfortunately due to the ongoing reliability issues with Firebase Auth and AppCheck which keeps us from being able to stop the rampant SMS fraud costing us a decent amount every month, we have begun a gradual migration away to Twilio.

vpusher commented 3 months ago

Hi Folks. We are facing the same issue with 10% to 20% of our clients calls ending up with Error Code: 16. The big issue for us is that it seems there is no workaround (except disabling AppCheck). Even uninstalling / installing the App from the App Store or TestFlight does not work. The concerned device are kind of stuck and cannot login anymore.

Our setup:

Our AppDelegate:

func application(_ application: UIApplication, didFinishLaunchingWithOptions launchOptions: [UIApplication.LaunchOptionsKey : Any]? = nil) -> Bool {
        let useEmulators = UserSettings.standard.environmentLevel == .local
        let filePath = Bundle.main.path(forResource: "GoogleService-Info.\(UserSettings.standard.environmentLevel.ext)", ofType: "plist")

        guard let filePath = filePath, let firebaseOptions = FirebaseOptions(contentsOfFile: filePath) else {
            assert(false, "Couldn't load config file")
            return false
        }

        if !useEmulators {
            #if DEBUG
            let providerFactory = AppCheckDebugProviderFactory()
            #else
            let providerFactory = FinanceAppCheckProviderFactory()
            #endif
            AppCheck.setAppCheckProviderFactory(providerFactory)
        }

        FirebaseApp.configure(options: firebaseOptions)
        Analytics.setAnalyticsCollectionEnabled(true)

        Loggers.firebase.debug("Loaded \(filePath)")
        Loggers.main.debug("\(ProcessInfo.processInfo.arguments)")

        UNUserNotificationCenter.current().delegate = self
        application.registerForRemoteNotifications()
        Messaging.messaging().delegate = self
        Auth.auth().useAppLanguage()

        if useEmulators {
            Loggers.firebase.debug("Using Emulators")
            // Auth Emulator
            Auth.auth().useEmulator(withHost:"localhost", port: 9099)
            // Firestore Emulator
            let settings = Firestore.firestore().settings
            settings.host = "localhost:8080"
            settings.cacheSettings = MemoryCacheSettings()
            settings.isSSLEnabled = false
            Firestore.firestore().settings = settings
            // Storage Emulator
            Storage.storage().useEmulator(withHost:"localhost", port: 9199)
            // Functions Emulator
            Functions.functions().useEmulator(withHost: "localhost", port: 5001)
        } else {
            Loggers.firebase.debug("Using Live Instance")
        }

        return true
    }

How can we help to progress on that issue ?