InstanceProfileProvider: bug with Guzzle 7.0.1, works with 6.4.5

zzgab commented 4 years ago

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 S3Client used in the context of InstanceProfilePovider. The description is the same as #2022 Aws\Exception\CredentialsException Timeout, but it fails only with guzzlehttp/guzzle v7.0.1. The same SDK version on same instance (and same application) with guzzlehttp/guzzle v 6.5.4 works fine. Therefore I don't think that the issue is the EC2 instance being unable to respond quick enough.

Version of AWS SDK for PHP? v3.138.9 (but I believe it's the same with 3.145)

Version of PHP (php -v)? php 7.4

To Reproduce (observed behavior)

When running this code on an EC2 instance with an IAM role granting the appropriate S3 permissions:

$client = new S3Client([
    'version' => 'latest',
    'region' => 'us-east-1,
]);

$client->getObject([
  'Bucket' => $bucket,
  'Key' => $key,
  'SaveAs' => $localFilename,
]);

with the Guzzlehttp version reported above (7.0.1): I get an exception:

Aws\\Exception\\CredentialsException
Code: 0
Message: Error retrieving credentials from the instance profile metadata service. (cURL error 28: Operation timed out after 1000 milliseconds with 0 bytes received (see https://curl.haxx.se/libcurl/c/libcurl-errors.html))
File: /srv/app/vendor/aws/aws-sdk-php/src/Credentials/InstanceProfileProvider.php
Line: 226
Trace:
#0 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(203): Aws\\Credentials\\InstanceProfileProvider->Aws\\Credentials\\{closure}()
#1 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(156): GuzzleHttp\\Promise\\Promise::callHandler()
#2 /srv/app/vendor/guzzlehttp/promises/src/TaskQueue.php(47): GuzzleHttp\\Promise\\Promise::GuzzleHttp\\Promise\\{closure}()
#3 /srv/app/vendor/guzzlehttp/guzzle/src/Handler/CurlMultiHandler.php(155): GuzzleHttp\\Promise\\TaskQueue->run()
#4 /srv/app/vendor/guzzlehttp/guzzle/src/Handler/CurlMultiHandler.php(182): GuzzleHttp\\Handler\\CurlMultiHandler->tick()
#5 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(246): GuzzleHttp\\Handler\\CurlMultiHandler->execute()
#6 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(223): GuzzleHttp\\Promise\\Promise->invokeWaitFn()
#7 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(267): GuzzleHttp\\Promise\\Promise->waitIfPending()
#8 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(225): GuzzleHttp\\Promise\\Promise->invokeWaitList()
#9 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(62): GuzzleHttp\\Promise\\Promise->waitIfPending()
#10 /srv/app/vendor/guzzlehttp/promises/src/Coroutine.php(65): GuzzleHttp\\Promise\\Promise->wait()
#11 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(246): GuzzleHttp\\Promise\\Coroutine->GuzzleHttp\\Promise\\{closure}()
#12 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(223): GuzzleHttp\\Promise\\Promise->invokeWaitFn()
#13 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(62): GuzzleHttp\\Promise\\Promise->waitIfPending()
#14 /srv/app/vendor/guzzlehttp/promises/src/Coroutine.php(85): GuzzleHttp\\Promise\\Promise->wait()
#15 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(273): GuzzleHttp\\Promise\\Coroutine->wait()
#16 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(225): GuzzleHttp\\Promise\\Promise->invokeWaitList()
#17 /srv/app/vendor/guzzlehttp/promises/src/Promise.php(62): GuzzleHttp\\Promise\\Promise->waitIfPending()
#18 /srv/app/vendor/aws/aws-sdk-php/src/AwsClientTrait.php(59): GuzzleHttp\\Promise\\Promise->wait()
#19 /srv/app/vendor/aws/aws-sdk-php/src/AwsClientTrait.php(87): Aws\\AwsClient->execute()

Expected behaviour

Exact same code, same machine, works fine if I downgrade guzzlehttp/guzzle to version 6.5.4.

diehlaws commented 4 years ago

Thanks for reaching out to us about this @zzgab. Unfortunately I haven't been able to reproduce the described behavior using the specified versions of PHP, the AWS SDK for PHP, and the Guzzle HTTP client. The following information should help us better troubleshoot this behavior.

Are you running your code directly on the EC2 instance, or within a Docker container running on the instance?
Are there any frameworks or other packages involved aside from the AWS SDK for PHP and Guzzle in the environment in which you see this behavior?
Do you see this behavior across multiple instances?
Do you see this behavior when attempting to reach the instance metadata service directly using Guzzle 7.0.1 or only when attempting to retrieve instance profile credentials via the AWS SDK for PHP?

The following code snippets result in successful attempts to retrieve credentials from the instance metadata service on t2.micro and t3a.large instances on my end.

SDK code

```php 'us-west-2', 'version' => 'latest', 'credentials' => $profile, ]); try { $resp = $client->listBuckets(); echo "Found " . sizeof($resp['Buckets']) . " buckets on attempt {$i}." . PHP_EOL; } catch (AwsException $e) { echo "S3 error: {$e->getMessage()}" . PHP_EOL; } } while (isset($e) !== true); ```

Guzzle code

```php request('GET', $credLocation); $code = $req->getStatusCode(); echo "Attempt {$i} statusCode: {$code}" . PHP_EOL; } catch (Exception $e) { echo "Request failed! {$e}" . PHP_EOL; } } while (isset($e) !== true); ```

zzgab commented 4 years ago

Hi @diehlaws, thanks for your quick response.

I can confirm that I do reproduce the behaviour, using your SDK snippet (slightly modified to avoid the infinite loop in case of success).

I run the application (and your snippet) not natively on the EC2 instance, but inside a Docker container (image: php:7.4.4-apache-buster)

The snippet works fine with

  "aws/aws-sdk-php": "3.145.4",
  "guzzlehttp/guzzle": "6.5.4"

(I read: "Found 5 buckets")

but it fails with :

  "aws/aws-sdk-php": "3.145.4",
  "guzzlehttp/guzzle": "7.0.1"

PHP Fatal error: Uncaught Aws\\Exception\\CredentialsException: Error retrieving credentials from the instance profile metadata service. (cURL error 28: Operation timed out after 1001 milliseconds with 0 bytes received

NB: I executed the snippet PHP file directly (direct HTTP request in public html, not through routing framework or dependency injection).

My complete require in composer.json is :

        "guzzlehttp/guzzle": "^7",
        "aws/aws-sdk-php": "^3.138.9",
        "phpmailer/phpmailer": "^6.1",
        "mailgun/mailgun-php": "^2.8",
        "kriswallsmith/buzz": "^1.1",
        "nyholm/psr7": "^1.1",
        "slim/slim": "^4.5",
        "php-di/php-di": "^6.2",
        "slim/psr7": "^1.1"

(but I don't think it has an effect on my current problem)

Please note that the Guzzle snippet works, including 7.0.1.

However, the environment does not contain an AWS_ROLENAME entry. I made the snippet work by hard-coding the role name. Just in case, I also tried to provide this env var to the first snippet (SDK) but this did not help.

Thanks for your help. Gabriel

Stollie commented 4 years ago

I had the same problem, running in a docker container with PHP 7.4. I also tried with 7.2 and 7.3 and got the same error.

Thanks for the info @zzgab, with downgrading guzzle to version 6 it works again. :)

I'm using the Symfony bundle and enabled the debug mode and ran the SQS pull. This was the output I hope it can be a bit of help.

GUZZLE 7.1

root@a47501698b36:/var/www# bin/console sms:callback-listener

-> Entering step init, name 'idempotency_auto_fill'
---------------------------------------------------

  command was set to array(3) {
    ["instance"]=>
    string(32) "000000005019f3e40000000001795f97"
    ["name"]=>
    string(14) "ReceiveMessage"
    ["params"]=>
    array(6) {
      ["QueueUrl"]=>
      string(86) "https://sqs.eu-central-1.amazonaws.com/xxx/xxx-staging-sms-service-callbacks"
      ["MaxNumberOfMessages"]=>
      int(10)
      ["WaitTimeSeconds"]=>
      int(5)
      ["MessageAttributeNames"]=>
      array(1) {
        [0]=>
        string(7) "Service"
      }
      ["@http"]=>
      array(2) {
        ["connect_timeout"]=>
        int(5)
        ["debug"]=>
        resource(1350) of type (stream)
      }
      ["@context"]=>
      array(0) {
      }
    }
  }

  request was set to array(0) {
  }

-> Entering step validate, name 'validation'
--------------------------------------------

  no changes

-> Entering step build, name 'builder'
--------------------------------------

  request.instance was set to 000000005019f1320000000001795f97
  request.method was set to POST
  request.headers was set to array(4) {
    ["X-Amz-Security-Token"]=>
    string(7) "[TOKEN]"
    ["Host"]=>
    array(1) {
      [0]=>
      string(30) "sqs.eu-central-1.amazonaws.com"
    }
    ["Content-Length"]=>
    array(1) {
      [0]=>
      string(3) "218"
    }
    ["Content-Type"]=>
    array(1) {
      [0]=>
      string(33) "application/x-www-form-urlencoded"
    }
  }

  request.body was set to Action=ReceiveMessage&Version=2012-11-05&QueueUrl=https%3A%2F%2Fsqs.eu-central-1.amazonaws.com%2Fxxxxxx%2Fxxxx-staging-sms-service-callbacks&MaxNumberOfMessages=10&WaitTimeSeconds=5&MessageAttributeName.1=Service
  request.scheme was set to https

-> Entering step build, name 'ApiCallMonitoringMiddleware'
----------------------------------------------------------

  no changes

-> Entering step build, name ''
-------------------------------

  request.instance changed from 000000005019f1320000000001795f97 to 000000005019f2ea0000000001795f97
  request.headers.User-Agent was set to array(1) {
    [0]=>
    string(46) "aws-sdk-php/3.145.4 Symfony/4.4.10 SYMOD/2.2.2"
  }

-> Entering step build, name 'endpoint_parameter'
-------------------------------------------------

  no changes

-> Entering step build, name 'EndpointDiscoveryMiddleware'
----------------------------------------------------------

  no changes

-> Entering step build, name 'sqs.queue_url'
--------------------------------------------

  request.instance changed from 000000005019f2ea0000000001795f97 to 000000005019efe50000000001795f97
  request.path was set to /xxxx/xxxx-staging-sms-service-callbacks

-> Entering step sign, name 'StreamRequestPayloadMiddleware'
------------------------------------------------------------

  no changes

-> Entering step sign, name 'invocation-id'
-------------------------------------------

  request.instance changed from 000000005019efe50000000001795f97 to 000000005019f35c0000000001795f97
  request.headers.aws-sdk-invocation-id was set to array(1) {
    [0]=>
    string(32) "5a35d880e7f7d4b573db971763739713"
  }

-> Entering step sign, name 'retry'
-----------------------------------

  request.instance changed from 000000005019f35c0000000001795f97 to 000000005019f4550000000001795f97
  request.headers.aws-sdk-retry was set to array(1) {
    [0]=>
    string(3) "0/0"
  }

<- Leaving step sign, name 'retry'
----------------------------------

  error was set to array(6) {
    ["instance"]=>
    string(32) "000000005019ee2c0000000001795f97"
    ["class"]=>
    string(34) "Aws\Exception\CredentialsException"
    ["message"]=>
    string(212) "Error retrieving credentials from the instance profile metadata service. (cURL error 28: Operation timed out after 8000 milliseconds with 0 bytes received (see https://curl.haxx.se/libcurl/c/libcurl-errors.html))"
    ["file"]=>
    string(75) "/var/www/vendor/aws/aws-sdk-php/src/Credentials/InstanceProfileProvider.php"
    ["line"]=>
    int(219)
    ["trace"]=>
    string(3187) "#0 /var/www/vendor/guzzlehttp/promises/src/Promise.php(203): Aws\Credentials\InstanceProfileProvider->Aws\Credentials\{closure}()
  #1 /var/www/vendor/guzzlehttp/promises/src/Promise.php(156): GuzzleHttp\Promise\Promise::callHandler()
  #2 /var/www/vendor/guzzlehttp/promises/src/TaskQueue.php(47): GuzzleHttp\Promise\Promise::GuzzleHttp\Promise\{closure}()
  #3 /var/www/vendor/guzzlehttp/guzzle/src/Handler/CurlMultiHandler.php(155): GuzzleHttp\Promise\TaskQueue->run()
  #4 /var/www/vendor/guzzlehttp/guzzle/src/Handler/CurlMultiHandler.php(182): GuzzleHttp\Handler\CurlMultiHandler->tick()
  #5 /var/www/vendor/guzzlehttp/promises/src/Promise.php(246): GuzzleHttp\Handler\CurlMultiHandler->execute()
  #6 /var/www/vendor/guzzlehttp/promises/src/Promise.php(223): GuzzleHttp\Promise\Promise->invokeWaitFn()
  #7 /var/www/vendor/guzzlehttp/promises/src/Promise.php(267): GuzzleHttp\Promise\Promise->waitIfPending()
  #8 /var/www/vendor/guzzlehttp/promises/src/Promise.php(225): GuzzleHttp\Promise\Promise->invokeWaitList()
  #9 /var/www/vendor/guzzlehttp/promises/src/Promise.php(62): GuzzleHttp\Promise\Promise->waitIfPending()
  #10 /var/www/vendor/guzzlehttp/promises/src/Coroutine.php(65): GuzzleHttp\Promise\Promise->wait()
  #11 /var/www/vendor/guzzlehttp/promises/src/Promise.php(246): GuzzleHttp\Promise\Coroutine->GuzzleHttp\Promise\{closure}()
  #12 /var/www/vendor/guzzlehttp/promises/src/Promise.php(223): GuzzleHttp\Promise\Promise->invokeWaitFn()
  #13 /var/www/vendor/guzzlehttp/promises/src/Promise.php(62): GuzzleHttp\Promise\Promise->waitIfPending()
  #14 /var/www/vendor/guzzlehttp/promises/src/Coroutine.php(85): GuzzleHttp\Promise\Promise->wait()
  #15 /var/www/vendor/guzzlehttp/promises/src/Promise.php(273): GuzzleHttp\Promise\Coroutine->wait()
  #16 /var/www/vendor/guzzlehttp/promises/src/Promise.php(225): GuzzleHttp\Promise\Promise->invokeWaitList()
  #17 /var/www/vendor/guzzlehttp/promises/src/Promise.php(62): GuzzleHttp\Promise\Promise->waitIfPending()
  #18 /var/www/vendor/aws/aws-sdk-php/src/AwsClientTrait.php(58): GuzzleHttp\Promise\Promise->wait()
  #19 /var/www/vendor/aws/aws-sdk-php/src/AwsClientTrait.php(86): Aws\AwsClient->execute()
  #20 /var/www/shared/src/Helper/Queue.php(81): Aws\AwsClient->__call()
  #21 /var/www/src/CallbackListener.php(80): XXXX\XXXX\Shared\Helper\Queue->poll()
  #22 /var/www/src/Command/CallbackListener.php(43): XXXX\XXXX\SMS\CallbackListener->run()
  #23 /var/www/vendor/symfony/console/Command/Command.php(255): XXXX\XXXX\SMS\Command\CallbackListener->execute()
  #24 /var/www/vendor/symfony/console/Application.php(1018): Symfony\Component\Console\Command\Command->run()
  #25 /var/www/vendor/symfony/framework-bundle/Console/Application.php(97): Symfony\Component\Console\Application->doRunCommand()
  #26 /var/www/vendor/symfony/console/Application.php(271): Symfony\Bundle\FrameworkBundle\Console\Application->doRunCommand()
  #27 /var/www/vendor/symfony/framework-bundle/Console/Application.php(83): Symfony\Component\Console\Application->doRun()
  #28 /var/www/vendor/symfony/console/Application.php(147): Symfony\Bundle\FrameworkBundle\Console\Application->doRun()
  #29 /var/www/bin/console(42): Symfony\Component\Console\Application->run()
  #30 {main}"
  }

  Inclusive step time: 8.0029730796814

<- Leaving step sign, name 'invocation-id'
------------------------------------------

  no changes
  Inclusive step time: 8.0031001567841

<- Leaving step sign, name 'StreamRequestPayloadMiddleware'
-----------------------------------------------------------

  no changes
  Inclusive step time: 8.0031859874725

<- Leaving step build, name 'sqs.queue_url'
-------------------------------------------

  no changes
  Inclusive step time: 8.0032851696014

<- Leaving step build, name 'EndpointDiscoveryMiddleware'
---------------------------------------------------------

  no changes
  Inclusive step time: 8.0038139820099

<- Leaving step build, name 'endpoint_parameter'
------------------------------------------------

  no changes
  Inclusive step time: 8.0038828849792

<- Leaving step build, name ''
------------------------------

  no changes
  Inclusive step time: 8.0039899349213

<- Leaving step build, name 'ApiCallMonitoringMiddleware'
---------------------------------------------------------

  no changes
  Inclusive step time: 8.0040919780731

<- Leaving step build, name 'builder'
-------------------------------------

  no changes
  Inclusive step time: 8.0059578418732

<- Leaving step validate, name 'validation'
-------------------------------------------

  no changes
  Inclusive step time: 8.0077810287476

<- Leaving step init, name 'idempotency_auto_fill'
--------------------------------------------------

  no changes
  Inclusive step time: 8.0082421302795

[2020-07-14 21:00:41] app.ERROR: Failed while listening for callback messages {"exception-message":"Error retrieving credentials from the instance profile metadata service. (cURL error 28: Operation timed out after 8000 milliseconds with 0 bytes received (see https://curl.haxx.se/libcurl/c/libcurl-errors.html))","exception-trace":"#0 /var/www/shared/src/Helper/Queue.php(85): XXXX\\XXX\\Shared\\Exception\\ReadException::fromThrowable()\n#1 /var/www/src/CallbackListener.php(80): XXXX\\XXXX\\Shared\\Helper\\Queue->poll()\n#2 /var/www/src/Command/CallbackListener.php(43): XXXX\\XXXX\\SMS\\CallbackListener->run()\n#3 /var/www/vendor/symfony/console/Command/Command.php(255): XXXX\\XXXX\\SMS\\Command\\CallbackListener->execute()\n#4 /var/www/vendor/symfony/console/Application.php(1018): Symfony\\Component\\Console\\Command\\Command->run()\n#5 /var/www/vendor/symfony/framework-bundle/Console/Application.php(97): Symfony\\Component\\Console\\Application->doRunCommand()\n#6 /var/www/vendor/symfony/console/Application.php(271): Symfony\\Bundle\\FrameworkBundle\\Console\\Application->doRunCommand()\n#7 /var/www/vendor/symfony/framework-bundle/Console/Application.php(83): Symfony\\Component\\Console\\Application->doRun()\n#8 /var/www/vendor/symfony/console/Application.php(147): Symfony\\Bundle\\FrameworkBundle\\Console\\Application->doRun()\n#9 /var/www/bin/console(42): Symfony\\Component\\Console\\Application->run()\n#10 {main}","exception-class":"XXXX\\XXXX\\Shared\\Exception\\ReadException"} []

gmponos commented 4 years ago

@Stollie maybe you could add also debug from 6.5.4 ?

Stollie commented 4 years ago

Here it is on PHP 7.2. From another container.

"message":"Starting sms:callback_listener worker.","context":[],"level":200,"level_name":"INFO","channel":"console","datetime":{"date":"2020-07-14 20:44:50.410765","timezone_type":3,"timezone":"Europe/Amsterdam"},"extra":[]}

-> Entering step init, name 'idempotency_auto_fill'
---------------------------------------------------

  command was set to array(3) {
    ["instance"]=>
    string(32) "00000000687bb20b00000000014b4bae"
    ["name"]=>
    string(14) "ReceiveMessage"
    ["params"]=>
    array(5) {
      ["QueueUrl"]=>
      string(86) "https://sqs.eu-central-1.amazonaws.com/XXXX/XXX-staging-sms-service-callbacks"
      ["MaxNumberOfMessages"]=>
      int(10)
      ["WaitTimeSeconds"]=>
      int(5)
      ["@http"]=>
      array(2) {
        ["connect_timeout"]=>
        int(5)
        ["debug"]=>
        resource(438) of type (stream)
      }
      ["@context"]=>
      array(0) {
      }
    }
  }

  request was set to array(0) {
  }

-> Entering step validate, name 'validation'
--------------------------------------------

  no changes

-> Entering step build, name 'builder'
--------------------------------------

  request.instance was set to 00000000687bb23900000000014b4bae
  request.method was set to POST
  request.headers was set to array(4) {
    ["X-Amz-Security-Token"]=>
    string(7) "[TOKEN]"
    ["Host"]=>
    array(1) {
      [0]=>
      string(30) "sqs.eu-central-1.amazonaws.com"
    }
    ["Content-Length"]=>
    array(1) {
      [0]=>
      string(3) "187"
    }
    ["Content-Type"]=>
    array(1) {
      [0]=>
      string(33) "application/x-www-form-urlencoded"
    }
  }

  request.body was set to Action=ReceiveMessage&Version=2012-11-05&QueueUrl=https%3A%2F%2Fsqs.eu-central-1.amazonaws.com%2FXXXX%2FXXXX-staging-sms-service-callbacks&MaxNumberOfMessages=10&WaitTimeSeconds=5
  request.scheme was set to https

-> Entering step build, name 'ApiCallMonitoringMiddleware'
----------------------------------------------------------

  no changes

-> Entering step build, name ''
-------------------------------

  request.instance changed from 00000000687bb23900000000014b4bae to 00000000687bb2c200000000014b4bae
  request.headers.User-Agent was set to array(1) {
    [0]=>
    string(19) "aws-sdk-php/3.138.7"
  }

-> Entering step build, name 'endpoint_parameter'
-------------------------------------------------

  no changes

-> Entering step build, name 'EndpointDiscoveryMiddleware'
----------------------------------------------------------

  no changes

-> Entering step build, name 'sqs.queue_url'
--------------------------------------------

  request.instance changed from 00000000687bb2c200000000014b4bae to 00000000687bb2cf00000000014b4bae
  request.path was set to /XXXX/XXXX-staging-sms-service-callbacks

-> Entering step sign, name 'StreamRequestPayloadMiddleware'
------------------------------------------------------------

  no changes

-> Entering step sign, name 'invocation-id'
-------------------------------------------

  request.instance changed from 00000000687bb2cf00000000014b4bae to 00000000687bb2c500000000014b4bae
  request.headers.aws-sdk-invocation-id was set to array(1) {
    [0]=>
    string(32) "a77f24a0116454e7e221d7622118a101"
  }

-> Entering step sign, name 'retry'
-----------------------------------

  request.instance changed from 00000000687bb2c500000000014b4bae to 00000000687bb2d700000000014b4bae
  request.headers.aws-sdk-retry was set to array(1) {
    [0]=>
    string(3) "0/0"
  }

-> Entering step sign, name 'signer'
------------------------------------

  request.instance changed from 00000000687bb2d700000000014b4bae to 00000000687bb2b300000000014b4bae
  request.headers.X-Amz-Date was set to array(1) {
    [0]=>
    string(16) "20200714T184451Z"
  }

  request.headers.Authorization was set to array(1) {
    [0]=>
    string(215) "AWS4-HMAC-SHA256 Credential=[KEY]/20200714/eu-central-1/sqs/aws4_request, SignedHeaders=host;x-amz-date;x-amz-security-token, Signature=[SIGNATURE]
  }

-> Entering step sign, name 'sqs.md5'
-------------------------------------

  no changes

-> Entering step attempt, name 'ApiCallAttemptMonitoringMiddleware'
-------------------------------------------------------------------

  no changes

*   Trying 52.119.190.137...
* TCP_NODELAY set
* Connected to sqs.eu-central-1.amazonaws.com (52.119.190.137) port 443 (#0)
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-SHA
* ALPN, server did not agree to a protocol
* Server certificate:
*  subject: CN=sqs.eu-central-1.amazonaws.com
*  start date: Jun  1 00:00:00 2020 GMT
*  expire date: May 12 12:00:00 2021 GMT
*  subjectAltName: host "sqs.eu-central-1.amazonaws.com" matched cert's "sqs.eu-central-1.amazonaws.com"
*  issuer: C=US; O=Amazon; OU=Server CA 1B; CN=Amazon
*  SSL certificate verify ok.
> POST /XXXX/XXXX-staging-sms-service-callbacks HTTP/1.1
Host: sqs.eu-central-1.amazonaws.com
Content-Type: application/x-www-form-urlencoded
aws-sdk-invocation-id: a77f24a0116454e7e221d7622118a101
aws-sdk-retry: 0/0
X-Amz-Date: 20200714T184451Z
X-Amz-Security-Token: IQoJb3JpZ2luX2VjEOr//////////wEaDGV1LWNlbnRyYWwtMSJHMEUCIQCmDKO94loAEZ26+HMhvDTtqENkY3gPqw7E14X4p55C3gIgSesdMDFM+Hm/xmoCBu2hbYdyIghQGKIJHHkEMfj2iC4qwwMIk///////////ARAAGgwzMTQwOTMyMDA5ODYiDEuKsjmxqS9JSL0tKCqXA0+xxRrGjQTm3WM2x3IEkMEVp9ze+zw4iiRjh06yHmDfbOW0pA8ylPHLpRqXiRiyqa/hfyXMlCDQXoIGO1TxD5Lw/ZqkoN/V3henzJ+swB1JKIXSq6UHDCeu22XCe1dMLeteI/KU3LwXG/b1kzyTrMm6wJ/0IjCqsLxxIEAgvv5Ja1hmvoiwFhMYar6Zt9CLgOKhci76mmqFo5Vcv1XWch2xLcG4VsrR/BeMc/hR6TUMHH3LIuHhWuMprrOXrMpk+PN29jjj7f3/nvczItd3RXvoIoX+TFWKChcJM1VE61LOAm0YJWeSRDSJdEaZ094u8syictV+Rmv/XeaM4ftISyRnqMkgJ5RJ3OjYjjqLIo5zgfhIHbRwo8mPoUNf8bkgfsUbtr3+cu/e+pxAioJ/srWoS4ocEcSSy9qw/Zxc+LmZsaSEOrzvY0J0W8AbrekPBpf92w9ykwebZbQK/U2wLsHlak1MVOavxFWyhnzVFVEiU7wlH1cniH9EqwxYF57xkQoNG40yD9gT/7zxeEpoJ7h86Tn8g8WZMObpt/gFOusB9R5ry25s/+J4lvtTuW4w7rAcIIm2HT4HhUMX8x46AxD22prrYvDN1EoiUjx4pDtWUaN8QJkLxaINEHfC40BYnY2lQ9wjhVk1u6xGx8qvtcJgPQRRmJimqXaft4uYn8B0mqZ2LVxQO9cQajqoAhbvcy8GvIQEHZnZnuKakGrZNvs/XMobW8LLmb3AvWh5KB7YDDbUnnLQBg1DkpI8JTt9q0LeoH9IDHLzrYGOMGhLHKm291h/YZ0wcpvIB6nNAsJpva6D6+ueQEai0dfJMouENlS8z3NIYOolN2Q9hVibyLeMJjViq4jf1gKiLA==
Authorization: AWS4-HMAC-SHA256 Credential=[KEY]/20200714/eu-central-1/sqs/aws4_request, SignedHeaders=host;x-amz-date;x-amz-security-token, Signature=[SIGNATURE]
User-Agent: aws-sdk-php/3.138.7 GuzzleHttp/6.5.4 curl/7.58.0 PHP/7.2.30-1+ubuntu18.04.1+deb.sury.org+1
Content-Length: 187

* upload completely sent off: 187 out of 187 bytes
< HTTP/1.1 200 OK
< x-amzn-RequestId: ce2580df-e038-56ff-9750-d7581f5bcf50
< Date: Tue, 14 Jul 2020 18:44:56 GMT
< Content-Type: text/xml
< Content-Length: 240
< 
* Connection #0 to host sqs.eu-central-1.amazonaws.com left intact

<- Leaving step attempt, name 'ApiCallAttemptMonitoringMiddleware'
------------------------------------------------------------------

  result was set to array(2) {
    ["instance"]=>
    string(32) "00000000687bb29800000000014b4bae"
    ["data"]=>
    array(1) {
      ["@metadata"]=>
      array(4) {
        ["statusCode"]=>
        int(200)
        ["effectiveUri"]=>
        string(86) "https://sqs.eu-central-1.amazonaws.com/XXXX/XXXX-staging-sms-service-callbacks"
        ["headers"]=>
        array(4) {
          ["x-amzn-requestid"]=>
          string(36) "ce2580df-e038-56ff-9750-d7581f5bcf50"
          ["date"]=>
          string(29) "Tue, 14 Jul 2020 18:44:56 GMT"
          ["content-type"]=>
          string(8) "text/xml"
          ["content-length"]=>
          string(3) "240"
        }
        ["transferStats"]=>
        array(0) {
        }
      }
    }
  }

  Inclusive step time: 5.068382024765

<- Leaving step sign, name 'sqs.md5'
------------------------------------

  no changes
  Inclusive step time: 5.0684871673584

<- Leaving step sign, name 'signer'
-----------------------------------

  no changes
  Inclusive step time: 5.0686249732971

<- Leaving step sign, name 'retry'
----------------------------------

  no changes
  Inclusive step time: 6.0765919685364

<- Leaving step sign, name 'invocation-id'
------------------------------------------

  result.data.@metadata.transferStats.http was set to array(1) {
    [0]=>
    array(0) {
    }
  }

  Inclusive step time: 6.076758146286

<- Leaving step sign, name 'StreamRequestPayloadMiddleware'
-----------------------------------------------------------

  no changes
  Inclusive step time: 6.07683801651

<- Leaving step build, name 'sqs.queue_url'
-------------------------------------------

  no changes
  Inclusive step time: 6.076966047287

<- Leaving step build, name 'EndpointDiscoveryMiddleware'
---------------------------------------------------------

  no changes
  Inclusive step time: 6.0774369239807

<- Leaving step build, name 'endpoint_parameter'
------------------------------------------------

  no changes
  Inclusive step time: 6.0775148868561

<- Leaving step build, name ''
------------------------------

  no changes
  Inclusive step time: 6.0776221752167

<- Leaving step build, name 'ApiCallMonitoringMiddleware'
---------------------------------------------------------

  no changes
  Inclusive step time: 6.077712059021

<- Leaving step build, name 'builder'
-------------------------------------

  no changes
  Inclusive step time: 6.0787029266357

<- Leaving step validate, name 'validation'
-------------------------------------------

  no changes
  Inclusive step time: 6.07985496521

<- Leaving step init, name 'idempotency_auto_fill'
--------------------------------------------------

  no changes
  Inclusive step time: 6.0804550647736

-> Entering step init, name 'idempotency_auto_fill'
---------------------------------------------------

  command was set to array(3) {
    ["instance"]=>
    string(32) "00000000687bb29800000000014b4bae"
    ["name"]=>
    string(14) "ReceiveMessage"
    ["params"]=>
    array(5) {
      ["QueueUrl"]=>
      string(86) "https://sqs.eu-central-1.amazonaws.com/XXXX/XXXX-staging-sms-service-callbacks"
      ["MaxNumberOfMessages"]=>
      int(10)
      ["WaitTimeSeconds"]=>
      int(5)
      ["@http"]=>
      array(2) {
        ["connect_timeout"]=>
        int(5)
        ["debug"]=>
        resource(489) of type (stream)
      }
      ["@context"]=>
      array(0) {
      }
    }
  }

  request was set to array(0) {
  }

-> Entering step validate, name 'validation'
--------------------------------------------

  no changes

-> Entering step build, name 'builder'
--------------------------------------

  request.instance was set to 00000000687bb22900000000014b4bae
  request.method was set to POST
  request.headers was set to array(4) {
    ["X-Amz-Security-Token"]=>
    string(7) "[TOKEN]"
    ["Host"]=>
    array(1) {
      [0]=>
      string(30) "sqs.eu-central-1.amazonaws.com"
    }
    ["Content-Length"]=>
    array(1) {
      [0]=>
      string(3) "187"
    }
    ["Content-Type"]=>
    array(1) {
      [0]=>
      string(33) "application/x-www-form-urlencoded"
    }
  }

  request.body was set to Action=ReceiveMessage&Version=2012-11-05&QueueUrl=https%3A%2F%2Fsqs.eu-central-1.amazonaws.com%2FXXXX%2FXXXX-staging-sms-service-callbacks&MaxNumberOfMessages=10&WaitTimeSeconds=5
  request.scheme was set to https

-> Entering step build, name 'ApiCallMonitoringMiddleware'
----------------------------------------------------------

  no changes

-> Entering step build, name ''
-------------------------------

  request.instance changed from 00000000687bb22900000000014b4bae to 00000000687bb22d00000000014b4bae
  request.headers.User-Agent was set to array(1) {
    [0]=>
    string(19) "aws-sdk-php/3.138.7"
  }

-> Entering step build, name 'endpoint_parameter'
-------------------------------------------------

  no changes

-> Entering step build, name 'EndpointDiscoveryMiddleware'
----------------------------------------------------------

  no changes

-> Entering step build, name 'sqs.queue_url'
--------------------------------------------

  request.instance changed from 00000000687bb22d00000000014b4bae to 00000000687bb22f00000000014b4bae
  request.path was set to /XXXX/XXXX-staging-sms-service-callbacks

-> Entering step sign, name 'StreamRequestPayloadMiddleware'
------------------------------------------------------------

  no changes

-> Entering step sign, name 'invocation-id'
-------------------------------------------

  request.instance changed from 00000000687bb22f00000000014b4bae to 00000000687bb22e00000000014b4bae
  request.headers.aws-sdk-invocation-id was set to array(1) {
    [0]=>
    string(32) "c2cda7455eeb6c7c26f681a7070eb4e7"
  }

-> Entering step sign, name 'retry'
-----------------------------------

  request.instance changed from 00000000687bb22e00000000014b4bae to 00000000687bb22100000000014b4bae
  request.headers.aws-sdk-retry was set to array(1) {
    [0]=>
    string(3) "0/0"
  }

-> Entering step sign, name 'signer'
------------------------------------

  request.instance changed from 00000000687bb22100000000014b4bae to 00000000687bb23600000000014b4bae
  request.headers.X-Amz-Date was set to array(1) {
    [0]=>
    string(16) "20200714T184456Z"
  }

  request.headers.Authorization was set to array(1) {
    [0]=>
    string(215) "AWS4-HMAC-SHA256 Credential=[KEY]/20200714/eu-central-1/sqs/aws4_request, SignedHeaders=host;x-amz-date;x-amz-security-token, Signature=[SIGNATURE]
  }

-> Entering step sign, name 'sqs.md5'
-------------------------------------

  no changes

-> Entering step attempt, name 'ApiCallAttemptMonitoringMiddleware'
-------------------------------------------------------------------

  no changes

* Found bundle for host sqs.eu-central-1.amazonaws.com: 0x55adc406d790 [can pipeline]
* Re-using existing connection! (#0) with host sqs.eu-central-1.amazonaws.com
* Connected to sqs.eu-central-1.amazonaws.com (52.119.190.137) port 443 (#0)
> POST /XXXX/XXXX-staging-sms-service-callbacks HTTP/1.1
Host: sqs.eu-central-1.amazonaws.com
Content-Type: application/x-www-form-urlencoded
aws-sdk-invocation-id: c2cda7455eeb6c7c26f681a7070eb4e7
aws-sdk-retry: 0/0
X-Amz-Date: 20200714T184456Z
X-Amz-Security-Token:
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
Authorization: AWS4-HMAC-SHA256 Credential=[KEY]/20200714/eu-central-1/sqs/aws4_request, SignedHeaders=host;x-amz-date;x-amz-security-token, Signature=[SIGNATURE]
User-Agent: aws-sdk-php/3.138.7 GuzzleHttp/6.5.4 curl/7.58.0 PHP/7.2.30-1+ubuntu18.04.1+deb.sury.org+1
Content-Length: 187

* upload completely sent off: 187 out of 187 bytes
< HTTP/1.1 200 OK
< x-amzn-RequestId: ec8e4ffb-19e6-55d6-bc65-187ce68e3c79
< Date: Tue, 14 Jul 2020 18:44:59 GMT
< Content-Type: text/xml
< Content-Length: 879
< 
* Connection #0 to host sqs.eu-central-1.amazonaws.com left intact

<- Leaving step attempt, name 'ApiCallAttemptMonitoringMiddleware'
------------------------------------------------------------------

  result was set to array(2) {
    ["instance"]=>
    string(32) "00000000687bad4100000000014b4bae"
    ["data"]=>
    array(2) {
      ["Messages"]=>
      array(1) {
        [0]=>
        array(4) {
          ["MessageId"]=>
          string(36) "acf3fd6c-dbe8-4766-b4cd-98b62492cfef"
          ["ReceiptHandle"]=>
          string(432) "AQEBWG8BWF6ay8xHCAennf/L8gEyVPaAHzZsvIfBuro3fSZHSHtltaFZUL5k16/OB8ZW6E32ckeFUOFB+3ieY4tZeEBE5Dnl709ht1S70ueiXsztZAA95OibBJvZNq4o1yLml8Mux7oHhy9o7SqjLMYO8DgEGSw7DJ/a6kETDt8mMdFKwHrMf4nHWpN79dc4P729erBmMwpaF6VsX87wh7WGoDJ0hksDjMDM7jfwBm/5LF+IpBSMxgSsywRSRbOGlXI3uSMW0RCrMiCOcAWnzy6eURoCf293dgKfcoTiRDds8Qb+7LTEOJJEw2ncYDNvdS0y2Xckd+irUZsKeiMQSDibk4qCZKyatr/hCZKxjZhaiDIHBgYMuF/+iB1a+jIVsNq/LuC2XosZk8r4C5llOfSSi6mlQEpAUAZ9SQdBSOh41Hc="
          ["MD5OfBody"]=>
          string(32) "f5d26ea16607c0a6fd477c5456f19c61"
          ["Body"]=>
          string(8) "{'lolz'}"
        }
      }
      ["@metadata"]=>
      array(4) {
        ["statusCode"]=>
        int(200)
        ["effectiveUri"]=>
        string(86) "https://sqs.eu-central-1.amazonaws.com/XXXX/XXXX-staging-sms-service-callbacks"
        ["headers"]=>
        array(4) {
          ["x-amzn-requestid"]=>
          string(36) "ec8e4ffb-19e6-55d6-bc65-187ce68e3c79"
          ["date"]=>
          string(29) "Tue, 14 Jul 2020 18:44:59 GMT"
          ["content-type"]=>
          string(8) "text/xml"
          ["content-length"]=>
          string(3) "879"
        }
        ["transferStats"]=>
        array(0) {
        }
      }
    }
  }

  Inclusive step time: 2.9128079414368

<- Leaving step sign, name 'sqs.md5'
------------------------------------

  no changes
  Inclusive step time: 2.9129831790924

<- Leaving step sign, name 'signer'
-----------------------------------

  no changes
  Inclusive step time: 2.9131119251251

<- Leaving step sign, name 'retry'
----------------------------------

  no changes
  Inclusive step time: 2.9135529994965

<- Leaving step sign, name 'invocation-id'
------------------------------------------

  result.data.@metadata.transferStats.http was set to array(1) {
    [0]=>
    array(0) {
    }
  }

  Inclusive step time: 2.9137141704559

<- Leaving step sign, name 'StreamRequestPayloadMiddleware'
-----------------------------------------------------------

  no changes
  Inclusive step time: 2.9138050079346

<- Leaving step build, name 'sqs.queue_url'
-------------------------------------------

  no changes
  Inclusive step time: 2.9139029979706

<- Leaving step build, name 'EndpointDiscoveryMiddleware'
---------------------------------------------------------

  no changes
  Inclusive step time: 2.9140079021454

<- Leaving step build, name 'endpoint_parameter'
------------------------------------------------

  no changes
  Inclusive step time: 2.9140779972076

<- Leaving step build, name ''
------------------------------

  no changes
  Inclusive step time: 2.9141919612885

<- Leaving step build, name 'ApiCallMonitoringMiddleware'
---------------------------------------------------------

  no changes
  Inclusive step time: 2.9142911434174

<- Leaving step build, name 'builder'
-------------------------------------

  no changes
  Inclusive step time: 2.9144718647003

<- Leaving step validate, name 'validation'
-------------------------------------------

  no changes
  Inclusive step time: 2.9147379398346

<- Leaving step init, name 'idempotency_auto_fill'
--------------------------------------------------

  no changes
  Inclusive step time: 2.9148960113525

{"message":"Found messages in queue","context":{"sqs-queue-url":"https://sqs.eu-central-1.amazonaws.com/XXXX/XXXX-staging-sms-service-callbacks","message-count":1},"level":200,"level_name":"INFO","channel":"console","datetime":{"date":"2020-07-14 20:44:59.407136","timezone_type":3,"timezone":"Europe/Amsterdam"},"extra":[]}

# composer info guzzlehttp/guzzle
name     : guzzlehttp/guzzle
descrip. : Guzzle is a PHP HTTP client library
keywords : client, curl, framework, http, http client, rest, web service
versions : * 6.5.4
type     : library
license  : MIT License (MIT) (OSI approved) https://spdx.org/licenses/MIT.html#licenseText
homepage : http://guzzlephp.org/
source   : [git] https://github.com/guzzle/guzzle.git a4a1b6930528a8f7ee03518e6442ec7a44155d9d
dist     : [zip] https://api.github.com/repos/guzzle/guzzle/zipball/a4a1b6930528a8f7ee03518e6442ec7a44155d9d a4a1b6930528a8f7ee03518e6442ec7a44155d9d
path     : /home/annabel/sms/vendor/guzzlehttp/guzzle
names    : guzzlehttp/guzzle

autoload
psr-4
GuzzleHttp\ => src/
files

requires
ext-json *
guzzlehttp/promises ^1.0
guzzlehttp/psr7 ^1.6.1
php >=5.5
symfony/polyfill-intl-idn 1.17.0

requires (dev)
ext-curl *
phpunit/phpunit ^4.8.35 || ^5.7 || ^6.4 || ^7.0
psr/log ^1.1

suggests
psr/log Required for using the Log middleware

out-of-band commented 4 years ago

Just confirming this bug as well.

In our case, we were running into Error retrieving credentials from the instance profile metadata service. trying to send messages via SES from pods running in EKS using IAM via service account with the eks.amazonaws.com/role-arn annotation.

We were fairly certain from the beginning of troubleshooting that this was something specific to the AWS PHP SDK since we have Node.js applications running on the same cluster under the same service account using SES/SNS/SQS without issue.

But can confirm that rolling Guzzle back to 6.5.4 fixed the issue.

fischaz commented 4 years ago

Hi all,

I believe we have the same issue (reading the ticket and the condition). debugging internally, in our case, we've narrowed it down to the way the PHP/Guzzle first try to access the AWS Metadata v2 Token API http://169.254.169.254/latest/api/token which:

does connect with TCP
but times out waiting for the PUT call to respond.

I could reproduce the issue within the same docker container using curl:

curl -X PUT -v http://169.254.169.254/latest/api/token -H "X-aws-ec2-metadata-token-ttl-seconds: 21600"

Strangely, the same curl command was successful on the host itself, so there is something fishy on the way AWS might deal with the docker network and the token API call.

Also, access to any other EC2 metadata endpoint (like the direct Ec2 credentials endpoint) is still working from within the container normally with or without the token header (because we don't enforce metadata V2 just yet).

I believe this might explain why the older version of guzzle is working as it might not yet have implemented the code to use metadata v2 access.

I'll have to dig further on my side as to why AWS metadata v2 token API access is timeout within a docker container (this does not quite make sense yet from a TCP/HTTP point of view).

Hopefully this is helpful.

fischaz commented 4 years ago

This is a generic docker bridge network issue accessing that token API:

Per https://aws.amazon.com/blogs/security/defense-in-depth-open-firewalls-reverse-proxies-ssrf-vulnerabilities-ec2-instance-metadata-service/ (specifically the Protecting against open layer 3 firewalls and NATs)

the return packet has a TTL of 1, and as a bridge container is 2 hops away, the return packet of the response of the HTTP GET call never gets back (the TCP SYN-ACK will have usual TTL which is why TCP established normally).

In our case, I can work around the problem with a simple iptables rule:

iptables -t mangle -A PREROUTING -i eth0 -m tcp -p tcp -s 169.254.169.254 --sport
80 -m ttl --ttl 1 -j TTL --ttl-set 2

Disclaimer, this is a security change which would defeat the protection AWS implemented. Please use at your own risk.

I'm not sure if that's the ideal approach, but that's one way of fixing it.

gmponos commented 4 years ago

@fischaz even if that's the issue.. how does this explain that it works with Guzzle6? Do you have any idea?

fischaz commented 4 years ago

That I cannot explain. if guzzle only takes care of the HTTP aspect of things, it should fail the same way when the Ec2Metadata class tries to query the endpoint with guzzle (v6 or v7)... Sorry...

thorstenmathar commented 4 years ago

iptables -t mangle -A PREROUTING -i eth0 -m tcp -p tcp -s 169.254.169.254 --sport 80 -m ttl --ttl 1 -j TTL --ttl-set 2

a better way might be to use

aws ec2 modify-instance-metadata-options --instance-id .... --http-put-response-hop-limit 2

to set the instance metadata options, because this can be done for launch configurations and templates too.

howardlopez commented 4 years ago

a better way might be to use

aws ec2 modify-instance-metadata-options --instance-id .... --http-put-response-hop-limit 2

to set the instance metadata options, because this can be done for launch configurations and templates too.

This is the recommended way of dealing with this use case. For more context, EC2 has a guide on configuring IMDSv2.

fischaz commented 4 years ago

I was not aware of this, this is indeed a better workaround for this issue.

fischaz commented 4 years ago

regarding this issue, could it be because Guzzle refactored in V7 their exceptions?

eg in 7.0.0-beta2, there is the entry:

ConnectException extends TransferException #2541

and looking (admittedly at master in github, not the specific tag) at the guzzle code (https://github.com/guzzle/guzzle/blob/master/src/Handler/CurlFactory.php#L205) my view is that guzzle is not throwing a RequestException (bad headers), but a ConnectException which is not in the same 'extends tree'.

now the InstanceCredentials (https://github.com/aws/aws-sdk-php/blob/master/src/Credentials/InstanceProfileProvider.php#L215) specifically look for a RequestException (I guess that's what it used to do in v6) to catch/re-throw for the _invoke (https://github.com/aws/aws-sdk-php/blob/master/src/Credentials/InstanceProfileProvider.php#L84) to catch and ignore....

but as v7 throws a different exception, this goes to the next case which is not caught and the exception is final.

would that make sense?

julianosilva94 commented 4 years ago

this problem occurred with me using aws sdk php version 3.113.0

howardlopez commented 4 years ago

Thanks for your insight, everyone!

@fischaz This does look a case of the thrown exceptions changing in Guzzle 7, and we've added a fix in #2117 that will go out in the next release.

Let us know if anyone still has any issues.

zzgab commented 4 years ago

@howardlopez Thanks!

aws / aws-sdk-php

InstanceProfileProvider: bug with Guzzle 7.0.1, works with 6.4.5 #2057