Aws-sdk-php: Token file not found temporarily after refresh on Kubernetes

[alecwcp]

Confirm by changing [ ] to [x] below to ensure that it's a bug:

• [x] I've gone though Developer Guide and API reference
• [x] I've checked AWS Forums and StackOverflow for answers
• [x] I've searched for previous similar issues and didn't find any solution

Describe the bug
When using the PHP SDK within a Kubernetes pod, using IAM roles for service accounts (https://docs.aws.amazon.com/eks/latest/userguide/iam-roles-for-service-accounts.html), with the default provider chain, the credentials are fetched by \Aws\Credentials\AssumeRoleWithWebIdentityCredentialProvider from the file identified by the environment variable with name \Aws\Credentials\CredentialProvider::ENV_TOKEN_FILE (in our case, the file is /var/run/secrets/eks.amazonaws.com/serviceaccount/token - this is coming from using IAM roles for service accounts). At some point after a token refresh the next time the SDK attempts to fetch the token https://github.com/aws/aws-sdk-php/blob/32a4fa88dffc4328d415b922ef74819dfe060696/src/Credentials/AssumeRoleWithWebIdentityCredentialProvider.php#L97 it isn't found, the credentials provider goes down the chain and ends up throwing Aws\Exception\CredentialsException with message

Error retrieving credentials from the instance profile metadata server. (cURL error 7: Failed to connect to 169.254.169.254 port 80: Connection refused (see https://curl.haxx.se/libcurl/c/libcurl-errors.html))

Version of AWS SDK for PHP?
3.133.6

Version of PHP (php -v)?
7.3.13

To Reproduce (observed behavior)
Create a Kubernetes pod using the default provider chain (retrieving credentials from a token file) and set a short refresh period for the token (to see the issue sooner). The code below recreates the client on each loop - in production code we only create it once now, but the issue still occurs because we're using PHP FPM and the realpath cache stays with the child worker, so is not cleared on each request

<?php
require 'vendor/autoload.php';
use Aws\S3\S3Client;
use Aws\Exception\AwsException;
use Aws\Credentials\CredentialProvider;
const WAIT_TIME_IN_SECONDS = 10;
while (true) {
    //Create a S3Client
    $s3Client = new S3Client([
        //'profile' => 'default',
        'region' => 'us-west-2',
        'version' => '2006-03-01'
    ]);
    $date = date('Y-m-d H:i:s');
    echo sprintf('%s Sleeping %s seconds%s', $date, WAIT_TIME_IN_SECONDS, PHP_EOL);
    sleep(WAIT_TIME_IN_SECONDS);
    //Listing all S3 Bucket
    $buckets = $s3Client->listBuckets();
    foreach ($buckets['Buckets'] as $bucket) {
//        echo sprintf(' %s%s', $bucket['Name'], PHP_EOL);
    }
}

Expected behavior
The token file should always be successfully retrieved if it is present.

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

Additional context
The issue appears to be related to the realpath cache (the issue relates to reading Kubernetes secrets, which this post highlights as hitting issues with the realpath cache https://pracucci.com/php-realpath-cache-and-kubernetes-secrets-configmap-updates.html) .
The token file is a symlink. When the token is refreshed this symlink changes, meaning the PHP realpath cache entry for this becomes invalid. So the next time the line https://github.com/aws/aws-sdk-php/blob/32a4fa88dffc4328d415b922ef74819dfe060696/src/Credentials/AssumeRoleWithWebIdentityCredentialProvider.php#L97 is reached the token file isn't found.

We alleviated the issue by manually clearing the realpath cache for this file before creating the SDK client, but it is still hit upon occasion.
We believe that changing the highlighted line in \Aws\Credentials\AssumeRoleWithWebIdentityCredentialProvider to

$token = file_get_contents($this->tokenFile);
if (false === $token) {
    clearstatcache(true, $this->tokenFile);
    $token = file_get_contents($this->tokenFile);
}

would resolve this.

[diehlaws]

Thanks for bringing this to our attention @alecwcp. The description you've provided for the behavior shown makes sense, on the surface this does appear to be a bug in the way the AWS SDK for PHP handles fetching the web identity token once the token is refreshed. I'll work on reproducing this to ensure the proposed fix works as expected, once I have more information on this I'll update the issue accordingly.

[diehlaws]

Thanks for your patience in this matter @alecwcp. Unfortunately I haven't been able to reproduce the described behavior on my end, once the web identity token expires the SDK seems to be able to locate the new one without issues on my end. I created an image using version 1.133.6 of the SDK with a modified AssumeRoleWithWebIdentityProvider to expose the token file's realpath just before $token is set:

echo "Using Web Identity Token Credential Provider" . PHP_EOL;
$tokenExists = file_exists($this->tokenFile);
echo "Token file is at {$this->tokenFile}" . PHP_EOL . "realpath: "; echo realpath($this->tokenFile); echo PHP_EOL;
echo "Token exists: ";
echo ($tokenExists ? "yes" : "no"); echo PHP_EOL;
$token = file_get_contents($this->tokenFile);

I set my service account token to expire every 600 seconds and modified your code sample to run in an EKS pod with the ServiceAccount enabled:

Script:

<?php
require './vendor/autoload.php';
use Aws\S3\S3Client;
use Aws\Credentials\CredentialProvider;
use Aws\Exception\AwsException;
const WAIT_TIME_IN_SECONDS = 120;

echo "Using AWS SDK for PHP version " . Aws\Sdk::VERSION . PHP_EOL;

$provider = CredentialProvider::assumeRoleWithWebIdentityCredentialProvider();

$count = 0;
$startDate = time();

while (true) {
    //Create a S3Client

    $s3Client = new S3Client([
        //'profile' => 'default',
        'provider' => $provider,
        'region' => 'us-west-2',
        'version' => '2006-03-01'
    ]);
    $date = date('Y-m-d H:i:s');

    //Listing all S3 Bucket
   try {
        $buckets = $s3Client->listBuckets();
        // foreach ($buckets['Buckets'] as $bucket) {
        //    echo sprintf(' %s%s', $bucket['Name'], PHP_EOL);
        // }
        echo "Found " . sizeof($buckets['Buckets']) . " buckets." . PHP_EOL;
    } catch (AwsException $e) {
        echo "Error listing buckets: {$e->getMessage()}" . PHP_EOL;
    }
    $count++;
    $runMins = (time() - $startDate) / 60;
    echo "###" . PHP_EOL . "Token retrieved {$count} times" . PHP_EOL;
    echo "Script has been running for {$runMins} min" . PHP_EOL . "###" . PHP_EOL;
    echo sprintf('%s Sleeping %s seconds%s', $date, WAIT_TIME_IN_SECONDS, PHP_EOL);
    sleep(WAIT_TIME_IN_SECONDS);
}

After letting it run for about 15 minutes I saw the token's realpath change to the appropriate location once the initial token's expiration was reached:

Output:

Using AWS SDK for PHP version 3.133.6
Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_05_29_21_52_55.898089038/token
Token exists: yes
Found 50 buckets.
###
Token retrieved 1 times
Script has been running for 0.083333333333333 min
###
2020-05-29 21:53:02 Sleeping 120 seconds
Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_05_29_21_52_55.898089038/token
Token exists: yes
Found 50 buckets.
###
Token retrieved 2 times
Script has been running for 2.1833333333333 min
###
2020-05-29 21:55:07 Sleeping 120 seconds
Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_05_29_21_52_55.898089038/token
Token exists: yes
Found 50 buckets.
###
Token retrieved 3 times
Script has been running for 4.2666666666667 min
###
2020-05-29 21:57:13 Sleeping 120 seconds
Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_05_29_21_52_55.898089038/token
Token exists: yes
Found 50 buckets.
###
Token retrieved 4 times
Script has been running for 6.3666666666667 min
###
2020-05-29 21:59:18 Sleeping 120 seconds
Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_05_29_21_52_55.898089038/token
Token exists: yes
Found 50 buckets.
###
Token retrieved 5 times
Script has been running for 8.45 min
###
2020-05-29 22:01:24 Sleeping 120 seconds
Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_05_29_22_02_01.048533680/token
Token exists: yes
Found 50 buckets.
###
Token retrieved 6 times
Script has been running for 10.533333333333 min
###
2020-05-29 22:03:29 Sleeping 120 seconds
Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_05_29_22_02_01.048533680/token
Token exists: yes
Found 50 buckets.
###
Token retrieved 7 times
Script has been running for 12.633333333333 min
###
2020-05-29 22:05:34 Sleeping 120 seconds
Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_05_29_22_02_01.048533680/token
Token exists: yes
Found 50 buckets.
###
Token retrieved 8 times
Script has been running for 14.716666666667 min
###
2020-05-29 22:07:40 Sleeping 120 seconds
Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_05_29_22_02_01.048533680/token
Token exists: yes
Found 50 buckets.
###
Token retrieved 9 times
Script has been running for 16.816666666667 min
###
2020-05-29 22:09:45 Sleeping 120 seconds

On the 6th attempt to retrieve the token you can see that the realpath changes from /run/secrets/eks.amazonaws.com/serviceaccount/..2020_05_29_21_52_55.898089038/token to /run/secrets/eks.amazonaws.com/serviceaccount/..2020_05_29_22_02_01.048533680/token, as a result it seems like the SDK's AssumeRoleWithWebIdentityProvider appears to be working as expected here.

Unfortunately the cause of the behavior you're seeing isn't clear here, however having more details about your environment may help us better troubleshoot this issue. One thing that strikes me as odd is that the request to the instance metadata is returning a Connection refused error - I would suspect that the instance metadata would return a 404 - Not Found error in the event that the SDK is requesting a nonexistent path from IMDS.

[alecwcp]

Thanks for the thorough investigation @diehlaws

I'll ask our devops team to help me get some more environment details - is there anything in particular that would be useful?
I suspect they can also explain why the IMDS returns Connection refused (I'm a little hazy on how the IMDS works).

One thing that strikes me in the code you tested with is

const WAIT_TIME_IN_SECONDS = 120;

but since the default value of realpath_cache_ttl is also 120 seconds the script you used might be hitting the token file again just as it drops out of the realpath cache. Do you still get the same result if you decrease the sleep time (in the script we managed to hit it with we used 10 seconds)?

[mf-lit]

Hi @diehlaws , I've been working with @alecwcp on this....

I've taken your version of the script and your modifications to AssumeRoleWithWebIdentityProvider and have been running some tests.

Like you, I was unable to reproduce the issue at first, but then I reduced the wait time to just 10s and was able to reproduce it straight away:

Output

Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_06_05_11_08_22.977864363/token
Token exists: yes
Found 20 buckets.
###
Token retrieved 50 times
Script has been running for 8.9833333333333 min
###
2020-06-05 11:17:22 Sleeping 10 seconds
Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_06_05_11_08_22.977864363/token
Token exists: yes

Warning: file_get_contents(/var/run/secrets/eks.amazonaws.com/serviceaccount/token): failed to open stream: No such file or directory in /vendor/aws/aws-sdk-php/src/Credentials/AssumeRoleWithWebIdentityCredentialProvider.php on line 102
Error listing buckets: Error executing "ListBuckets" on "https://s3.us-west-2.amazonaws.com/"; AWS HTTP error: Client error: `GET https://s3.us-west-2.amazonaws.com/` resulted in a `403 Forbidden` response:
<?xml version="1.0" encoding="UTF-8"?>
<Error><Code>AccessDenied</Code><Message>Access Denied</Message><RequestId>0A1233 (truncated...)
 AccessDenied (client): Access Denied - <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>AccessDenied</Code><Message>Access Denied</Message><RequestId>0A1233D1B3BBA1A5</RequestId><HostId>TWqDUiFCK4/Nqc/41ErPhIqRvJEGcoEvxP8hvH+nbtnGCqpHd1+Qj8SnNgXunzCX50Lceb62QAA=</HostId></Error>
###
Token retrieved 51 times
Script has been running for 9.1666666666667 min

Service account token expiry is set to 600s, so we can see that the error occurs very close to that. Indeed, leaving the script running we reliably see errors start appearing shortly before expiry time and those errors continue for up to two minutes before recovering.

At this point I spent a lot of (too much) time trying to figure out what was happening as far as the caching was concerned. Eventually ending up with this madness:

AssumeRoleWithWebIdentityProvider

$token = file_get_contents($this->tokenFile);
if (false === $token) {
    echo json_encode(realpath_cache_get()[$this->tokenFile] ?? null) . PHP_EOL;
    echo "Token file is at {$this->tokenFile}" . PHP_EOL . "realpath: "; echo realpath($this->tokenFile); echo PHP_EOL;
    echo sprintf('Failed to get token, clearing cache "%s" naively', $this->tokenFile) . PHP_EOL;
    clearstatcache(true, $this->tokenFile);
    echo json_encode(realpath_cache_get()[$this->tokenFile] ?? null) . PHP_EOL;
    $token = file_get_contents($this->tokenFile);
    if (false === $token) {
        $firstLinkResolvedPath = dirname($this->tokenFile) . '/' . readlink($this->tokenFile);
        echo sprintf('Failed to get token, clearing cache "%s" (first link resolved)', $firstLinkResolvedPath) . PHP_EOL;
        clearstatcache(true, $firstLinkResolvedPath);
        echo json_encode(realpath_cache_get()[$this->tokenFile] ?? null) . PHP_EOL;
        $token = file_get_contents($this->tokenFile);
        if (false === $token) {
            echo sprintf('Failed to get token, clearing cache with realpath "%s"', realpath($this->tokenFile)) . PHP_EOL;
            clearstatcache(true, realpath($this->tokenFile));
            echo json_encode(realpath_cache_get()[$this->tokenFile] ?? null) . PHP_EOL;
            $token = file_get_contents($this->tokenFile);
            if (false === $token) {
                echo "Failed to get token, nuke cache" . PHP_EOL;
                clearstatcache(true);
                echo json_encode(realpath_cache_get()[$this->tokenFile] ?? null) . PHP_EOL;
                $token = file_get_contents($this->tokenFile);
            }
        }
    }
}

Basically what we're trying to do there is find a way to flush the token file path from the cache, quite how to do this is unclear as the token file path is a series of nested symlinks.

Running the above results in this:

Output

2020-06-05 16:34:22 Sleeping 10 seconds
Using Web Identity Token Credential Provider
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_06_05_16_25_31.274127243/token
Token exists: yes
Warning: file_get_contents(/var/run/secrets/eks.amazonaws.com/serviceaccount/token): failed to open stream: No such file or directory in /vendor/aws/aws-sdk-php/src/Credentials/AssumeRoleWithWebIdentityCredentialProvider.php on line 102
{"key":3420403952397616396,"is_dir":false,"realpath":"\/run\/secrets\/eks.amazonaws.com\/serviceaccount\/..2020_06_05_16_25_31.274127243\/token","expires":1591374960}
Token file is at /var/run/secrets/eks.amazonaws.com/serviceaccount/token
realpath: /run/secrets/eks.amazonaws.com/serviceaccount/..2020_06_05_16_25_31.274127243/token
Failed to get token, clearing cache "/var/run/secrets/eks.amazonaws.com/serviceaccount/token" naively
null
Warning: file_get_contents(/var/run/secrets/eks.amazonaws.com/serviceaccount/token): failed to open stream: No such file or directory in /vendor/aws/aws-sdk-php/src/Credentials/AssumeRoleWithWebIdentityCredentialProvider.php on line 109
Failed to get token, clearing cache "/var/run/secrets/eks.amazonaws.com/serviceaccount/..data/token" (first link resolved)
{"key":3420403952397616396,"is_dir":false,"realpath":"\/run\/secrets\/eks.amazonaws.com\/serviceaccount\/..2020_06_05_16_25_31.274127243\/token","expires":1591374993}
Warning: file_get_contents(/var/run/secrets/eks.amazonaws.com/serviceaccount/token): failed to open stream: No such file or directory in /vendor/aws/aws-sdk-php/src/Credentials/AssumeRoleWithWebIdentityCredentialProvider.php on line 115
Failed to get token, clearing cache with realpath "/run/secrets/eks.amazonaws.com/serviceaccount/..2020_06_05_16_25_31.274127243/token"
{"key":3420403952397616396,"is_dir":false,"realpath":"\/run\/secrets\/eks.amazonaws.com\/serviceaccount\/..2020_06_05_16_25_31.274127243\/token","expires":1591374993}
Warning: file_get_contents(/var/run/secrets/eks.amazonaws.com/serviceaccount/token): failed to open stream: No such file or directory in /vendor/aws/aws-sdk-php/src/Credentials/AssumeRoleWithWebIdentityCredentialProvider.php on line 120
Failed to get token, nuke cache
null
Found 20 buckets.
###

So we can see that clearing the entire cache solves the issue, but clearing the cache more specifically (both following and not following the symlinks) does not.

I'm at a bit of a dead-end at this point. I'm convinced caching is the underlying issue, indeed clearing the entire cache solves the problem. However clearing the entire cache isn't really a sensible solution and clearing just the specific entries has so far proved ineffective.

[mf-lit]

Having spent some more time on this I'm now certain that caching is the problem, and can report that the following paths must be cleared from cache in order to prevent a stale filesystem read:

/var/run/secrets/eks.amazonaws.com/serviceaccount/..data/token
/var/run/secrets/eks.amazonaws.com/serviceaccount/..data
/var/run/secrets/eks.amazonaws.com/serviceaccount/token

All three of those paths must be cleared and they must be in cleared in that order. It seems that otherwise PHP can still find partial matches to paths in-cache as it resolves the chain of symlinks and can end up going down a stale path as result.

So alecwcp's suggested fix can be modified like so for example:

$token = file_get_contents($this->tokenFile);
if (false === $token) {
  clearstatcache(true, dirname($this->tokenFile) . "/" . readlink($this->tokenFile));
  clearstatcache(true, dirname($this->tokenFile) . "/" . dirname(readlink($this->tokenFile)));
  clearstatcache(true, $this->tokenFile);
  $token = file_get_contents($this->tokenFile);   
}

With the above code I am no longer observing any errors.

[DZDomi]

Thank you everybody for the investigation so far! Is there any ETA when this fix will be released? As i think its already very clear where the issue is and can be solved with the 3 lines for clearstatcache from @mf-lit

[diehlaws]

@alecwcp @mf-lit thanks for the additional context and thorough investigation here, and I do apologize for the delay in response on our end. During my initial testing I increased the wait time for the sake of reducing the output to read through, inadvertently matching the realpath_cache_ttl value. Bringing the wait time back down to 10 seconds does indeed result in the behavior you describe, and implementing the suggested fix to clear these three paths does result in the new tokenfile being picked up as expected once the previously cached tokenfile expires. I'll be submitting a PR shortly for this fix, once it is merged this behavior should be resolved in the following release.

[DZDomi]

@diehlaws as the fix is already working as expected, is this something which can be merged into the aws sdk in the foreseeable future? as we are still waiting on this and we are getting still a lot of error logs daily from this bug.