Aws-sdk-android: No cached session if app is inactive for some time

[esathamzaj]

Describe the bug
If the app isn't used for some time, when initialize method gets called the user state is SIGNED_IN but when getTokens is called this log is printed and no exception is thrown, even if the getTokens async method with callback is called neither onResult or onError is called. There is no way of knowing that getTokens has failed, as no exception is thrown, the only way to fix this was to add a listener addUserStateListener(listener) that in that case would change the userState to SIGNED_OUT_USER_POOLS_TOKENS_INVALID, i guess the bug here is that when initialize is called wrong user state is provided in this case SIGNED_IN instead of SIGNED_OUT_USER_POOLS_TOKENS_INVALID

To Reproduce
Don't interact with the app for a few days, when the user

Which AWS service(s) are affected?

Expected behavior
A clear and concise description of what you expected to happen.

Screenshots
If applicable, add screenshots to help explain your problem.

Environment Information (please complete the following information):
com.amazonaws:aws-android-sdk-mobile-client:2.16.12@aar { transitive = true }
com.amazonaws:aws-android-sdk-auth-userpools:2.16.12@aar { transitive = true }
com.amazonaws:aws-android-sdk-s3:2.16.12'

• Huawei Mate 20 Pro
  
  
  
  • Android Version: 9
  
  

Additional context
Add any other context about the problem here.

[jpignata]

Heya @esathamzaj! What have you set your token expiration period to in the user pool?

[esathamzaj]

We use the default 1 hour period expiration for access token and 30 days for refresh token

[jpignata]

Got it. Thanks. And you're seeing this for all users when "some time" is a value less than 30 days.

[esathamzaj]

Yes, this happens even before 30 days have passed.

[TrekSoft]

Hey @esathamzaj - dug into the code and see exactly why you're wrongly getting the state returned as SIGNED_IN and we could make a fix to address that. However, the more concerning issue is why the user pool tokens would be invalid after less than the 30 days. To troubleshoot this, can you log out userStateDetails.getException() from the UserStateDetails object returned by initialize and post that here?

[esathamzaj]

@TrekSoft the problem is that it wouldn't throw the exception, when initialising it would return the state SIGNED_IN as i explained above and when retrieving the token it would just log the screenshot above without throwing an exception.

[TrekSoft]

Yep I understand that. I was referring to getting the exception from inside the returned user state details object in Initialize but I now see on a closer look that field is protected so you won't actually have access to that. I'll add a bug to our backlog to make an immediate fix of initialize not returning SIGNED_IN but rather the proper state of SIGNED_OUT_USER_POOLS_TOKENS_INVALID and then another ticket to investigate why it's signing you out earlier than it seems it should.

[esathamzaj]

@TrekSoft sorry about the misunderstanding, okay then, thank you for the explanation. Please let me know if you have any updates regarding this.

[TrekSoft]

Will do!

[estiukamobi]

Any feedback on this issue, I am also facing the same problem.

[TrekSoft]

Nothing new on it yet but thanks for adding your +1 to help us in prioritizing it. Is your primary issue the fact it returns the wrong state or the fact that it signs you out earlier than it seems it should?

[estiukamobi]

The issue is getting the SIGN_IN state but the token fails to be refreshed.
From what I have seen, it seems to occur in _getCachedSession_ from CognitoUser

[TrekSoft]

I'm confused - what you described where it returns the cached token without refreshing when you call getTokens being SIGNED_IN is expected behavior. What part is unexpected?

[estiukamobi]

Sorry my bad, that was a different issue on our side, when our backend team temporarily changed the refresh token expiry.
I have checked again with our QA team and for the Sign-in issue, what we have sporadically spotted was a fresh sign-in, but immediately after the user is logged out.

They got a partial stacktrace:

AWSMobileClient: Inspecting user state details
AWSMobileClient: Inspecting user state details
AWSMobileClient: Inspecting user state details
AWSMobileClient: Sending password.
AWSMobileClient: _federatedSignIn: Putting provider and token in store
AWSMobileClient: Inspecting user state details
AWSMobileClient: hasFederatedToken: false provider: cognito-idp.eu-west-2.amazonaws.com/eu-west-2_TC0XCQMRB
AWSMobileClient: Failed to federate tokens during sign-in
    java.lang.RuntimeException: Error in federating the token.
        at com.amazonaws.mobile.client.AWSMobileClient$10.run(AWSMobileClient.java:1716)
        at com.amazonaws.mobile.client.internal.InternalCallback.await(InternalCallback.java:115)
        at com.amazonaws.mobile.client.AWSMobileClient.federatedSignInWithoutAssigningState(AWSMobileClient.java:1644)
        at com.amazonaws.mobile.client.AWSMobileClient$6$1.onSuccess(AWSMobileClient.java:1191)
        at com.amazonaws.mobileconnectors.cognitoidentityprovider.CognitoUser$6.onSuccess(CognitoUser.java:1099)
        at com.amazonaws.mobileconnectors.cognitoidentityprovider.CognitoUser$29.run(CognitoUser.java:3118)
        at com.amazonaws.mobileconnectors.cognitoidentityprovider.CognitoUser$24.run(CognitoUser.java:2965)
        at com.amazonaws.mobileconnectors.cognitoidentityprovider.continuations.AuthenticationContinuation.continueTask(AuthenticationContinuation.java:147)
        at com.amazonaws.mobile.client.AWSMobileClient$6$1.getAuthenticationDetails(AWSMobileClient.java:1222)
        at com.amazonaws.mobileconnectors.cognitoidentityprovider.CognitoUser.getSession(CognitoUser.java:1032)
        at com.amazonaws.mobile.client.AWSMobileClient$6.run(AWSMobileClient.java:1176)
        at com.amazonaws.mobile.client.internal.InternalCallback$1.run(InternalCallback.java:101)
        at java.lang.Thread.run(Thread.java:919)
     Caused by: com.amazonaws.services.cognitoidentity.model.NotAuthorizedException: Invalid login token. Couldn't verify signed token. (Service: AmazonCognitoIdentity; Status Code: 400; Error Code: NotAuthorizedException; Request ID: 51e24623-bcb9-426e-866f-03510aa1a0d1)
        at com.amazonaws.http.AmazonHttpClient.handleErrorResponse(AmazonHttpClient.java:731)
        at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:405)
        at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:212)
        at com.amazonaws.services.cognitoidentity.AmazonCognitoIdentityClient.invoke(AmazonCognitoIdentityClient.java:1728)
        at com.amazonaws.services.cognitoidentity.AmazonCognitoIdentityClient.getId(AmazonCognitoIdentityClient.java:809)
        at com.amazonaws.auth.AWSAbstractCognitoIdentityProvider.getIdentityId(AWSAbstractCognitoIdentityProvider.java:172)
        at com.amazonaws.mobile.client.AWSMobileClientCognitoIdentityProvider.refresh(AWSMobileClient.java:3885)
        at com.amazonaws.auth.CognitoCredentialsProvider.startSession(CognitoCredentialsProvider.java:679)
        at com.amazonaws.auth.CognitoCredentialsProvider.refresh(CognitoCredentialsProvider.java:632)
        at com.amazonaws.auth.CognitoCachingCredentialsProvider.refresh(CognitoCachingCredentialsProvider.java:511)
        at com.amazonaws.mobile.client.AWSMobileClient.federateWithCognitoIdentity(AWSMobileClient.java:1747)
        at com.amazonaws.mobile.client.AWSMobileClient$10.run(AWSMobileClient.java:1703)
        at com.amazonaws.mobile.client.internal.InternalCallback.await(InternalCallback.java:115) 
        at com.amazonaws.mobile.client.AWSMobileClient.federatedSignInWithoutAssigningState(AWSMobileClient.java:1644) 
        at com.amazonaws.mobile.client.AWSMobileClient$6$1.onSuccess(AWSMobileClient.java:1191) 
        at com.amazonaws.mobileconnectors.cognitoidentityprovider.CognitoUser$6.onSuccess(CognitoUser.java:1099) 
        at com.amazonaws.mobileconnectors.cognitoidentityprovider.CognitoUser$29.run(CognitoUser.java:3118) 
        at com.amazonaws.mobileconnectors.cognitoidentityprovider.CognitoUser$24.run(CognitoUser.java:2965) 
        at com.amazonaws.mobileconnectors.cognitoidentityprovider.continuations.AuthenticationContinuation.continueTask(AuthenticationContinuation.java:147) 
        at com.amazonaws.mobile.client.AWSMobileClient$6$1.getAuthenticationDetails(AWSMobileClient.java:1222) 
        at com.amazonaws.mobileconnectors.cognitoidentityprovider.CognitoUser.getSession(CognitoUser.java:1032) 
        at com.amazonaws.mobile.client.AWSMobileClient$6.run(AWSMobileClient.java:1176) 
        at com.amazonaws.mobile.client.internal.InternalCallback$1.run(InternalCallback.java:101) 
        at java.lang.Thread.run(Thread.java:919) 
AWSMobileClient: Inspecting user state details
AWSMobileClient: waitForSignIn: userState:SIGNED_OUT
AWSMobileClient: Inspecting user state details
AWSMobileClient: waitForSignIn: userState:SIGNED_OUT
AWSMobileClient: Inspecting user state details
AWSMobileClient: waitForSignIn: userState:SIGNED_OUT
AWSMobileClient: Inspecting user state details
AWSMobileClient: Inspecting user state details

Any idea why the token could not be verified, it is very sporadic.

[TrekSoft]

Alright this sounds like a different issue - could you create a new issue with the steps to reproduce and relevant code snippets?

[aleksnied]

Seeing the same issue as the original post. Is there any recommended workaround for this? Thanks

[aleksnied]

However, in our case, killing and restarting the app fixed the issue, without having to log out/log in (which makes me think that reporting SIGNED_OUT_USER_POOLS_TOKENS_INVALID) is not the correct solution, but that you are experiencing some in-memory bad caching inside the SDK that fails the token refresh after a few days of leaving the app open in the background. Will continue to investigate whether this is 100% the same issue as the one in this ticket

[aleksnied]

Another clue is this doesn't seem to happen for users that signed in with federated sign in (OKTA) but only username/password login directly with cognito

[TrekSoft]

Thanks for those details alek - we're going to be having a bug bash focus in a couple weeks here and hope to have time to investigate this then. In the meantime could you post the specific steps to reproduce what you're seeing and the specific logs you're seeing?

[aleksnied]

Hey! I think the issue I was reproducing today was actually down to something else sorry. The relevant error reports that led me here were as such:

Non-fatal Exception: java.lang.Exception
No cached session.
com.amazonaws.mobile.client.AWSMobileClient$11$1.signalTokensNotAvailable (AWSMobileClient.java:1856)
com.amazonaws.mobile.client.AWSMobileClient$11$1.getAuthenticationDetails (AWSMobileClient.java:1836)
com.amazonaws.mobileconnectors.cognitoidentityprovider.CognitoUser.getSession (CognitoUser.java:1032)
com.amazonaws.mobile.client.AWSMobileClient$11.run (AWSMobileClient.java:1817)
com.amazonaws.mobile.client.internal.InternalCallback$1.run (InternalCallback.java:101)
java.lang.Thread.run (Thread.java:919)

However this could be occurring for legitimate purposes and the userState machine might be functioning correctly. I'll let you know if I find additional evidence that it is not.

[aleksnied]

@TrekSoft
Had some more time to investigate this. I lowered the refresh token expiry to 1 hour to watch what happens.
When the refresh token times out, I don't ever get a call to the UserStateListener to mark SIGNED_OUT_USER_POOLS_TOKENS_INVALID as the new state. It remains as SIGNED_IN.
When launching the app fresh with a token that has expired, the state is also reported as SIGNED_IN right after initialisation (sounds like what you were describing above).
Effectively, the mechanism we were using relying on UserStateListener to sign the user out when the refresh token expires does not work anymore.
The only way to get the correct state is calling AWSMobileClient.getCurrentUserState(). That returns correctly.

[TrekSoft]

Thanks for that additional info! This is still definitely in our backlog to address.

[AnsabShohab]

Facing the same issue. Any updates on the fix?

[TrekSoft]

Not yet scheduled - keep +1ing this issue for priority.

[ansuman-CP]

I had the exact same issue. It happens when in the absence of internet connectivity i sign out -- make a call to AwsMobileClient.getInstance().signout(). Afterwards the application is in a weird state. On restarting the app, this time with internet connection, the initial userState check gives SIGNED_IN status and proceeds to the next fragment (say, NextFragment) where I access other AWS services. But when I try to access some service which required cognito access, I get error (CognitoUserSession: CognitoUserSession is not valid because idToken is null.) and (AWSMobileClient: signalTokensNotAvailable). AWS tries to re-login. I get this error -- AWSMobileClient: Tokens are invalid, please sign-in again. My question is : what check should I make in NextFragment to navigate the app to sign-in page again?

Note: I am not using Amplify. I have implemented all the methods of AwsMobileClient class related to the login flow.
This is the error log:
D/ForceDarkHelper: updateByCheckExcludeList: pkg: com.cellpropulsion.application.android.mobilityd.debug activity: com.cellpropulsion.application.android.mobilityd.ui.MainActivity@48fef9
D/ForceDarkHelper: updateByCheckExcludeList: pkg: com.cellpropulsion.application.android.mobilityd.debug activity: com.cellpropulsion.application.android.mobilityd.ui.MainActivity@48fef9
D/CognitoCachingCredentia: Loading credentials from SharedPreferences
D/KeyProvider23: AndroidKeyStore contains keyAlias com.amazonaws.android.auth.aesKeyStoreAlias
Loading the encryption key from Android KeyStore.
D/CognitoCachingCredentia: No valid credentials found in SharedPreferences
D/KeyProvider23: AndroidKeyStore contains keyAlias com.amazonaws.android.auth.aesKeyStoreAlias
Loading the encryption key from Android KeyStore.
W/LogFactory: Truncating log tag length as it exceed 23, the limit imposed by Android on certain API Levels
I/AWSKeyValueStore: Detected Android API Level = 29
Creating the AWSKeyValueStore with key for sharedPreferencesForData = CognitoIdentityProviderCache
D/KeyProvider23: AndroidKeyStore contains keyAlias com.amazonaws.mobile.client.aesKeyStoreAlias
D/KeyProvider23: Loading the encryption key from Android KeyStore.
D/AWSMobileClient: Inspecting user state details
D/C:StartFragment:102: signed-in...
D/KeyProvider23: AndroidKeyStore contains keyAlias com.amazonaws.mobile.client.aesKeyStoreAlias
Loading the encryption key from Android KeyStore.
D/ForceDarkHelper: updateByCheckExcludeList: pkg: com.cellpropulsion.application.android.mobilityd.debug activity: com.cellpropulsion.application.android.mobilityd.ui.MainActivity@48fef9
I/chatty: uid=10820(com.cellpropulsion.application.android.mobilityd.debug) identical 2 lines
D/KeyProvider23: AndroidKeyStore contains keyAlias com.amazonaws.mobile.client.aesKeyStoreAlias
Loading the encryption key from Android KeyStore.
D/C:DashboardFragment:53: onViewCreated() dashboardFragment...
D/KeyProvider23: AndroidKeyStore contains keyAlias com.amazonaws.mobile.client.aesKeyStoreAlias
Loading the encryption key from Android KeyStore.
D/AWSMobileClient: Inspecting user state details
D/KeyProvider23: AndroidKeyStore contains keyAlias com.amazonaws.mobile.client.aesKeyStoreAlias
Loading the encryption key from Android KeyStore.
D/KeyProvider23: AndroidKeyStore contains keyAlias CognitoIdentityProviderCache.aesKeyStoreAlias
Loading the encryption key from Android KeyStore.
D/ForceDarkHelper: updateByCheckExcludeList: pkg: com.cellpropulsion.application.android.mobilityd.debug activity: com.cellpropulsion.application.android.mobilityd.ui.MainActivity@48fef9
D/KeyProvider23: AndroidKeyStore contains keyAlias com.amazonaws.mobile.client.aesKeyStoreAlias
Loading the encryption key from Android KeyStore.
D/KeyProvider23: AndroidKeyStore contains keyAlias com.amazonaws.mobile.client.aesKeyStoreAlias

W/CognitoUserSession: CognitoUserSession is not valid because idToken is null.
W/AWSMobileClient: signalTokensNotAvailable
W/AWSMobileClient: Tokens are invalid, please sign-in again.
java.lang.Exception: No cached session.
at com.amazonaws.mobile.client.AWSMobileClient$11$1.signalTokensNotAvailable(AWSMobileClient.java:1801)
at com.amazonaws.mobile.client.AWSMobileClient$11$1.getAuthenticationDetails(AWSMobileClient.java:1781)
at com.amazonaws.mobileconnectors.cognitoidentityprovider.CognitoUser.getSession(CognitoUser.java:940)
at com.amazonaws.mobile.client.AWSMobileClient$11.run(AWSMobileClient.java:1763)
at com.amazonaws.mobile.client.internal.InternalCallback.await(InternalCallback.java:115)
at com.amazonaws.mobile.client.AWSMobileClient.getTokens(AWSMobileClient.java:1729)
at com.amazonaws.mobile.client.AWSMobileClient.getUserStateDetails(AWSMobileClient.java:1031)
at com.amazonaws.mobile.client.AWSMobileClient.waitForSignIn(AWSMobileClient.java:910)
at com.amazonaws.mobile.client.AWSMobileClient.getCredentials(AWSMobileClient.java:362)
at com.amazonaws.services.iot.AWSIotClient.invoke(AWSIotClient.java:11398)
at com.amazonaws.services.iot.AWSIotClient.attachPolicy(AWSIotClient.java:667)
at com.cellpropulsion.application.android.mobilityd.module.dashboard.viewmodel.DashboardViewModel$AttachPolicyTask.doInBackground(DashboardViewModel.java:103)
at com.cellpropulsion.application.android.mobilityd.module.dashboard.viewmodel.DashboardViewModel$AttachPolicyTask.doInBackground(DashboardViewModel.java:90)
at android.os.AsyncTask$3.call(AsyncTask.java:378)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:289)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:919)
D/AWSMobileClient: waitForSignIn: userState:SIGNED_OUT_USER_POOLS_TOKENS_INVALID
I/mobilityd.debu: ProcessProfilingInfo new_methods=2658 is saved saved_to_disk=1 resolve_classes_delay=8000