Refresh token expired earlier than it should on android application

[andrey-chorniy]

State your question
In our android application, the user logged-in at 2019, Jan 28 13:37:55 UTC. In less than 24 hours, at 2019, Jan 29 08:21:20 UTC the application received a user state change with state: SIGNED_OUT_USER_POOLS_TOKENS_INVALID
Before these 2 events the app performed authenticated actions (using AWSMobileClient.getInstance() as credentials provider) with such AWS services:

• AppSync
• DynamoDB
• S3

Initially, we created cognito user pool with default settings, e.g. app clients had default refresh token expiration time set to 30 days. Afterwards, to prevent expiration of credentials (which is the requirement of the app), we set refresh token expiration time to 3650 days (almost 10 years).
Note: log in happened after the refresh token lifetime was changed to 3650 days for app clients.

Questions:

1. Why could the application get logged out if refresh token lifetime was changed to 10 years?
2. Do the changes of refresh token lifetime take effect after the Cognito user pool is created?

Which AWS Services are you utilizing?
Cognito, DynamoDB, Lambda, AppSync, S3

Environment(please complete the following information):
SDK Version: 2.10.1

Device Information (please complete the following information):

• Device: [Samsung SM-J710FN, Xiaomi Mi5s]
• Android Version: [7.0, 8.0]

[andrey-chorniy]

auth-expired-logs.zip

[mutablealligator]

@andrey-chorniy Sorry for the delayed response. From the logs I could find this:

Event-1:

2019-01-29 08:18:43.761 +0000 UTC I CognitoCachingCredentialsProvider  Logcat:0 logcat   Saving credentials to SharedPreferences
2019-01-29 08:18:43.761 +0000 UTC I AWSMobileClient  Logcat:0 logcat   waitForSignIn: userState:SIGNED_IN
2019-01-29 08:18:43.761 +0000 UTC I AWSMobileClient  Logcat:0 logcat   getCredentials: Validated user is signed-in

At 08:18:43, the credentials were retrieved and saved to SharePreferences and AWSMobileClient gave a state change SIGNED_IN.

Event-2:

2019-01-29 08:21:09.567 +0000 UTC I AWSMobileClient  Logcat:0 logcat   Inspecting user state details

Event-3:

2019-01-29 08:21:09.638 +0000 UTC I AWSMobileClient  Logcat:0 logcat   Inspecting user state details

Event-4:

2019-01-29 08:21:20.123 +0000 UTC E AWSMobileClient  Logcat:0 logcat   signalTokensNotAvailable
2019-01-29 08:21:20.124 +0000 UTC E AWSMobileClient  Logcat:0 logcat   Tokens are invalid, please sign-in again.
2019-01-29 08:21:20.124 +0000 UTC I AWSMobileClient  Logcat:0 logcat   waitForSignIn: userState:SIGNED_OUT_USER_POOLS_TOKENS_INVALID
2019-01-29 08:21:20.125 +0000 UTC I ApplicationResources  Logcat:0 logcat   Tokens became invalid, state is SIGNED_OUT_USER_POOLS_TOKENS_INVALID
2019-01-29 08:21:20.132 +0000 UTC I SaveRawEventWorker  Logcat:0 logcat   Going to enqueue raw event for saving RawEvent(id=14e5db10-a0d7-48fc-87c0-a6ea976249b5, type=AuthenticationExpired, clientTime=1.548750080131E9, caseId=5644-sazel-b351fe49-cf80-4411-b099-0401a8f81d5e, participantId=5644-sazel-7114c868-19b4-4b3f-ac63-f3eccc621f54, officerId=null, agencyId=agency, deviceInfo=null, data={reason=Unknown})
2019-01-29 08:21:20.141 +0000 UTC I CognitoCachingCredentialsProvider  Logcat:0 logcat   Clearing credentials from SharedPreferences
2019-01-29 08:21:20.142 +0000 UTC I CognitoCachingCredentialsProvider  Logcat:0 logcat   Identity id is changed
2019-01-29 08:21:20.143 +0000 UTC I CognitoCachingCredentialsProvider  Logcat:0 logcat   Saving identity id to SharedPreferences
2019-01-29 08:21:20.143 +0000 UTC I CognitoCachingCredentialsProvider  Logcat:0 logcat   Clearing credentials from SharedPreferences
2019-01-29 08:21:20.143 +0000 UTC I IdentityManager  Logcat:0 logcat   Signing out...
2019-01-29 08:21:20.159 +0000 UTC I AWSMobileClient  Logcat:0 logcat   Inspecting user state details
2019-01-29 08:21:20.161 +0000 UTC I AWSMobileClient  Logcat:0 logcat   Inspecting user state details
2019-01-29 08:21:20.163 +0000 UTC I CognitoCachingCredentialsProvider  Logcat:0 logcat   Loading credentials from SharedPreferences
2019-01-29 08:21:20.163 +0000 UTC I CognitoCachingCredentialsProvider  Logcat:0 logcat   No valid credentials found in SharedPreferences
2019-01-29 08:21:20.169 +0000 UTC I System.out  Logcat:0 logcat   (HTTPLog)-Static: isSBSettingEnabled false

We are looking to debug this issue. So far we wrote a test that would signIn and check for the presence of tokens on the device. Advance the clock by 24 hours and then get tokens which uses the refresh token to retrieve a new access token which is different from the previous one and this seems to work.

1. Can you check if the app crashed between 13:37 and 08:20 and the app is launched again?
2. Do you have any change in the AWS region in the successive attempts?

[andrey-chorniy]

1. During the mentioned period there was a development of the app on device. And a couple of things certainly happened:
   • reinstalls
   • crashes of the app: 2019-01-28 15:54:38, 2019-01-28 15:54:50
2. We do not perform any actions with that user or Cognito settings (if that answers your question)

We also get other user reports about their credentials being expired (so they become logged out and have to login again).

[mutablealligator]

@andrey-chorniy Thank you for the quick response.

1. A reinstall will wipe the shared preferences since it is local to the app. I see that the last occurrence of SIGNED_IN was at 08:17 and SIGNED_OUT_USER_POOLS_TOKENS_INVALID at 08:20. Is there a chance that the app reinstall happened in this 3-minute window?

2. We have discovered the possibility of a bug in AWSMobileClient#isSignedIn which could result in this bug and we are investigating into it.

[andrey-chorniy]

@kvasukib On #1 - nope, under "re-install" we mean that we update the code and start a new version from AS, it was not uninstall/install cycle. So, SharedPreferrences should not be wiped out

On #2 - thanks, looking forward for possible reasons/fixes. One of our users do not re-install it (work with same app version) but got this error

[minbi]

Hi @andrey-chorniy ,

We have made some flow improvements. Please see if SDK release 2.12.5 fixes this issue for you. If not, we'll continue to investigate.

[andrey-chorniy]

@minbi We have got the same issue again on aws mobile sdk version 2.12.5

1. This user has signed in on March 18, 2019
2. On March 29, near 11:49 CDT the application version updated (from play store)
3. On March 30, at 1:27pm CDT the authentication tokens were invalidated according to the logs: Tokens are invalid, please sign-in again.

user-logs.txt

[saurabh947]

We're experiencing this issue as well - apparently as soon as the ID and Access tokens expire (one hour after they're issued) the AWSMobileClient.getInstance().currentUserState() always returns with SIGNED_OUT_USER_POOLS_TOKENS_INVALID state.
The refresh token in our case is set to expire in 90 days - which the SDK is not respecting.

Tested with AWS Mobile SDK v2.12.6, very similar to #815

[minbi]

Hi @saurabh947 ,

The currentUserState() method in version 2.12.6 would make a network call to refresh the tokens. If you called this method from a UI thread, it may cause the refresh to fail. We have released an async version currentUserState(Callback) to combat this scenario. If this does not explain you situation. Please provide some more information regarding your setup.

[minbi]

Hi @andrey-chorniy ,

I ran an experiment for an hour and I was able to get another set of userpools tokens and federate them into cognito identity pools. Please see my setup below.

MainActivity.java

package com.example.myapplication;

import android.support.v7.app.AppCompatActivity;
import android.os.Bundle;
import android.util.Log;
import android.view.View;
import android.widget.Toast;

import com.amazonaws.auth.AWSCredentials;
import com.amazonaws.mobile.client.AWSMobileClient;
import com.amazonaws.mobile.client.Callback;
import com.amazonaws.mobile.client.UserStateDetails;

public class MainActivity extends AppCompatActivity {
    public static final String TAG = MainActivity.class.getSimpleName();

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);

        AWSMobileClient.getInstance().initialize(this, new Callback<UserStateDetails>() {
            @Override
            public void onResult(UserStateDetails result) {
                Log.d(TAG, "onResult: " + result.getUserState());
            }

            @Override
            public void onError(Exception e) {
                Log.e(TAG, "onError: ", e);
            }
        });
    }

    public void signIn(final View view) {
        AWSMobileClient.getInstance().showSignIn(this, new Callback<UserStateDetails>() {
            @Override
            public void onResult(UserStateDetails result) {
                Log.d(TAG, "onResult: " + result.getUserState());
            }

            @Override
            public void onError(Exception e) {
                Log.e(TAG, "onError: ", e);
            }
        });
    }

    public void signOut(final View view) {
        AWSMobileClient.getInstance().signOut();
    }

    public void getCredentials(View view) {
        AWSMobileClient.getInstance().getAWSCredentials(new Callback<AWSCredentials>() {
            @Override
            public void onResult(final AWSCredentials awsCredentials) {
                runOnUiThread(new Runnable() {
                    @Override
                    public void run() {
                        Toast.makeText(MainActivity.this, awsCredentials.getAWSAccessKeyId() + "", Toast.LENGTH_LONG).show();
                    }
                });
            }

            @Override
            public void onError(final Exception e) {
                runOnUiThread(new Runnable() {
                    @Override
                    public void run() {
                        Log.e(TAG, "run: ", e);
                        Toast.makeText(MainActivity.this, e.getMessage() + "", Toast.LENGTH_LONG).show();
                    }
                });
            }
        });
    }
}

activity_main.xml

<?xml version="1.0" encoding="utf-8"?>
<LinearLayout xmlns:android="http://schemas.android.com/apk/res/android"
    xmlns:tools="http://schemas.android.com/tools"
    android:layout_width="match_parent"
    android:layout_height="match_parent"
    android:orientation="vertical"
    tools:context=".MainActivity">

    <Button
        android:text="sign-in"
        android:onClick="signIn"
        android:layout_width="match_parent"
        android:layout_height="wrap_content" />

    <Button
        android:text="sign-out"
        android:onClick="signOut"
        android:layout_width="match_parent"
        android:layout_height="wrap_content" />

    <Button
        android:text="get credentials"
        android:onClick="getCredentials"
        android:layout_width="match_parent"
        android:layout_height="wrap_content" />
</LinearLayout>

[minbi]

Hi @andrey-chorniy ,

I'm noticing in your logs that the "Tokens are invalid, please sign-in again." line does not include a stacktrace. Has this been truncated somewhere? The log should be writing the exception as seen here. The full exception would shed a lot of light into the scenario.

If you are able to reproduce this, can you use the Android Profiler to capture some network requests and responses during the "Tokens are invalid, please sign-in again." event?

[minbi]

Is it possible there is poor network conditions when the refresh is attempted?

[minbi]

Investigation notes:

Scenario 1: Sign-in, wait a day, call getCredentials() which triggers a refresh, new tokens are federated and new AWS credentials are returned.

Scenario 2: Sign-out, state is clear and simulates a problem when initializing AWSMobileClient, debug and force a "refresh" of empty credentials and empty state but injecting refresh token from previous day, new tokens are federated and new AWS credentials are returned.

Discoveries when testing: The refresh request requires the deviceKey to be sent if the remember device feature is enabled in the service.

[minbi]

When this scenario happens, you can also try calling releaseSignInWait() then attempting the getCredentials() call hierarchy again. This would attempt the refresh another time.

[saurabh947]

Hi @minbi

We have released an async version currentUserState(Callback) to combat this scenario.

I upgraded the SDK to latest version (v2.13.1 as of this writing) and this seems to have resolved our issue - Thanks for your help and quick resolution!

[frankmuellr]

Hi @andrey-chorniy, can you respond to @minbi's questions?

[andrey-chorniy]

@minibi @muellerfr

I'm noticing in your logs that the "Tokens are invalid, please sign-in again." line does not include a stacktrace. Has this been truncated somewhere?

It could be truncated. The logs are taken from bugfender https://bugfender.com

If you are able to reproduce this, can you use the Android Profiler to capture some network requests and responses during the "Tokens are invalid, please sign-in again." event?

Sure, we will try to do this in the team (however it's not easy to reproduce this, it may require hours of testing)

Is it possible there is poor network conditions when the refresh is attempted?

There definitely were the cases when the authentication expiration was preceeded by the numerous SocketTimeoutException's in the logs, but it's hard to say whether this was always the case. Our testing team experienced many cases with authentication token expiration.
Also, we were going to try to use 2.13.1 but we got S3-related issue with it. We suppose it will be addressed in the next update. See issue #899

[andrey-chorniy]

@minbi @muellerfr we still experience this issue on 2.13.2
Here is an example of sign-out SIGNED_OUT_USER_POOLS_TOKENS_INVALID which seems to be preceded with Network problems.

auth-on-2-13-2.txt

Interesting thing: we emulated exception to be thrown in AWSMobileClient.getUserStateDetails(), specifically we put a debug point in AWSMobileClient._getTokens(callback, waitForSignIn) and turned off internet connection before executing userpool.getCurrentUser().getSession(). Expectedly, Exception was thrown and in line which logs the exception
Log.w(TAG, tokens == null ? "Tokens are invalid, please sign-in again." : "Failed to federate the tokens", e); we got the exception java.lang.Exception: No cached session.

However: the exception stacktrace was not logged even in Logcat (displayed by android studio). Here are the logs which we took directly from Logcat:

2019-04-22 19:45:09.031 2999-3156/? D/WifiTrafficPoller: TrafficStats TxPkts=1873927 RxPkts=3736952 TxBytes=339625093 RxBytes=4689995485 , Foreground uid=10411 pkgName=com.ehawk.officer.staging txBytes=282040 rxBytes=72561
2019-04-22 19:45:09.213 21597-21697/com.ehawk.officer.staging W/AWSMobileClient: Tokens are invalid, please sign-in again.
2019-04-22 19:45:10.077 2999-3156/? D/WifiTrafficPoller: TrafficStats TxPkts=1873927 RxPkts=3736952 TxBytes=339625093 RxBytes=4689995485 , Foreground uid=10411 pkgName=com.ehawk.officer.staging txBytes=282040 rxBytes=72561

Update: we believe as long Exception is not printed then it was UnknownHostException which is not printed by Log.w()

[minbi]

Hi @andrey-chorniy ,

We are working on a fix that would expose network based exceptions without changing the state of the user. You may track its progress on this branch.

[stale]

This issue has been automatically closed because of inactivity. Please open a new issue if are still encountering problems.

[Andrew0000]

Looks like it happens on android emulators, not on real devices. But yes, it should be fixed.

Summary: cognito do nothing when access token expired (refresh token is actual) on android emulators (x86, not tested on arm).