Aws-sdk-go: Get credentials from role has become slow

[alexd765]

Please fill out the sections below to help us address your issue.

Version of AWS SDK for Go?

v1.25.41

Version of Go (go version)?

go version go1.11.1 linux/amd64

What issue did you see?

Getting credentials from an ec2 role takes 20 seconds.

We have this issue on consistently on multiple different ec2 instances since a couple of days ago.

To me it looks like an issue with the service, but I am not sure.

Steps to reproduce

package slow

import (
    "fmt"
    "time"

    "github.com/aws/aws-sdk-go/aws/credentials"
    "github.com/aws/aws-sdk-go/aws/credentials/ec2rolecreds"
    "github.com/aws/aws-sdk-go/aws/ec2metadata"
    "github.com/aws/aws-sdk-go/aws/session"
)

func getCredentialsFromRole() (*credentials.Credentials, error) {
    roleProvider := &ec2rolecreds.EC2RoleProvider{
        Client: ec2metadata.New(session.New()),
    }
    creds := credentials.NewCredentials(roleProvider)

    start := time.Now().UTC()
    if _, err := creds.Get(); err != nil { // this takes 20 seconds
        return nil, err
    }
    fmt.Printf("getting credentails from role took %s\n", time.Now().UTC().Sub(start))

    return creds, nil
}

[diehlaws]

Thanks for reaching out to us about this @alexd765. The behavior you describe sounds like it is taking a long time for the EC2 metadata service on your instance(s) to respond to a request for instance profile credentials. Do you see this behavior only on specific instance types/sizes? (If so, which ones?) Or does this occur consistently regardless of the instance type/size being used? Do you see a similar delay when attempting to reach the instance metadata service in a manner that does not involve the SDK (e.g. time curl http://169.254.169.254/latest/)?

[alexd765]

I see it on t2.micro, t2.small, c5.4xlarge.

We are in eu-west-1.

curl http://169.254.169.254/latest/ is instant on the affected machines.

Interestingly it is only getting the credentials from role that is slow. Getting credentials from environment vars is also instant.

[nlundbo]

We also saw similar behavior, we noticed issues on the operations

• S3 -> ListBuckets
• ec2MetadataService -> Region()
  both took 20+ seconds to complete. We noticed that going back to the previous version (for us it was v1.25.27) it was quick again. We saw the issue both in 1.25.40 and 1.25.41.

The above curl is also super-fast for us (only tested on t2.small)

[jasdel]

Thanks for raising this issue, @alexd765, @nlundbo. Is your application running in a Kubernetes pod, Docker container, or using any IP forwarding/proxy?

If so you may be impacted by a recent security change to EC2 instances, where the Instance Metadata service will limit the number of hops a request can make. Increasing hop limit on the instance should take care of long timeout issues on EC2 for customers who use any IP forwarding/proxying.

The EC2 ModifyInstanceMetadataOptions operation can be used to update the hop limit needed for your application's use case.

See https://docs.aws.amazon.com/AWSEC2/latest/UserGuide/ec2-instance-metadata.html for more information on EC2's IMDS update.

[nlundbo]

Yes, my use case was code inside a docker-container. I tested changing the number hops - and it resolved the issue. I read somewhere that it should not affect deployments in ECS - I have not verified this yet.

[pmalekn]

I'm also seeing this issue (I believe it's the same) and I've been able to pin point v1.25.38 as the culprit release.

Before v1.25.38 I can see the following requests being made by the sdk (when running on a docker container on EC2):

DEBU[2019-12-02T15:53:48.399Z] aws-sdk-message="[DEBUG: Request ec2metadata/GetMetadata Details:\n---[ REQUEST POST-SIGN ]-----------------------------\nGET /latest/meta-data/iam/security-credentials/ HTTP/1.1\r\nHost: 169.254.169.254\r\nUser-Agent: aws-sdk-go/1.25.37 (go1.13.4; linux; amd64)\r\nAccept-Encoding: gzip\r\n\r\n\n-----------------------------------------------------]"
DEBU[2019-12-02T15:53:48.4Z] aws-sdk-message="[DEBUG: Response ec2metadata/GetMetadata Details:\n---[ RESPONSE ]--------------------------------------\nHTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 38\r\nAccept-Ranges: none\r\nContent-Type: text/plain\r\nDate: Mon, 02 Dec 2019 15:53:48 GMT\r\nLast-Modified: Mon, 02 Dec 2019 14:55:48 GMT\r\nServer: EC2ws\r\n\r\n\n-----------------------------------------------------]"

while on v1.25.38 and newer:

DEBU[2019-12-02T16:00:54.872Z] aws-sdk-message="[DEBUG: Request ec2metadata/GetToken Details:\n---[ REQUEST POST-SIGN ]-----------------------------\nPUT /latest/api/token HTTP/1.1\r\nHost: 169.254.169.254\r\nUser-Agent: aws-sdk-go/1.25.38 (go1.13.4; linux; amd64)\r\nContent-Length: 0\r\nX-Aws-Ec2-Metadata-Token-Ttl-Seconds: 21600\r\nAccept-Encoding: gzip\r\n\r\n\n-----------------------------------------------------]"
DEBU[2019-12-02T16:00:59.873Z] aws-sdk-message="[DEBUG: Send Request ec2metadata/GetToken failed, attempt 0/3, error RequestError: send request failed\ncaused by: Put http://169.254.169.254/latest/api/token: net/http: request canceled (Client.Timeout exceeded while awaiting headers)]"
DEBU[2019-12-02T16:00:59.914Z] aws-sdk-message="[DEBUG: Request ec2metadata/GetToken Details:\n---[ REQUEST POST-SIGN ]-----------------------------\nPUT /latest/api/token HTTP/1.1\r\nHost: 169.254.169.254\r\nUser-Agent: aws-sdk-go/1.25.38 (go1.13.4; linux; amd64)\r\nContent-Length: 0\r\nX-Aws-Ec2-Metadata-Token-Ttl-Seconds: 21600\r\nAccept-Encoding: gzip\r\n\r\n\n-----------------------------------------------------]"
DEBU[2019-12-02T16:01:04.914Z] aws-sdk-message="[DEBUG: Send Request ec2metadata/GetToken failed, attempt 1/3, error RequestError: send request failed\ncaused by: Put http://169.254.169.254/latest/api/token: net/http: request canceled (Client.Timeout exceeded while awaiting headers)]"
DEBU[2019-12-02T16:01:05.009Z] aws-sdk-message="[DEBUG: Request ec2metadata/GetToken Details:\n---[ REQUEST POST-SIGN ]-----------------------------\nPUT /latest/api/token HTTP/1.1\r\nHost: 169.254.169.254\r\nUser-Agent: aws-sdk-go/1.25.38 (go1.13.4; linux; amd64)\r\nContent-Length: 0\r\nX-Aws-Ec2-Metadata-Token-Ttl-Seconds: 21600\r\nAccept-Encoding: gzip\r\n\r\n\n-----------------------------------------------------]"
DEBU[2019-12-02T16:01:10.009Z] aws-sdk-message="[DEBUG: Send Request ec2metadata/GetToken failed, attempt 2/3, error RequestError: send request failed\ncaused by: Put http://169.254.169.254/latest/api/token: net/http: request canceled (Client.Timeout exceeded while awaiting headers)]"
DEBU[2019-12-02T16:01:10.191Z] aws-sdk-message="[DEBUG: Request ec2metadata/GetToken Details:\n---[ REQUEST POST-SIGN ]-----------------------------\nPUT /latest/api/token HTTP/1.1\r\nHost: 169.254.169.254\r\nUser-Agent: aws-sdk-go/1.25.38 (go1.13.4; linux; amd64)\r\nContent-Length: 0\r\nX-Aws-Ec2-Metadata-Token-Ttl-Seconds: 21600\r\nAccept-Encoding: gzip\r\n\r\n\n-----------------------------------------------------]"
DEBU[2019-12-02T16:01:15.191Z] aws-sdk-message="[DEBUG: Send Request ec2metadata/GetToken failed, attempt 3/3, error RequestError: send request failed\ncaused by: Put http://169.254.169.254/latest/api/token: net/http: request canceled (Client.Timeout exceeded while awaiting headers)]"
// Fallback to "/latest/meta-data/iam/security-credentials/"
DEBU[2019-12-02T16:01:15.191Z] aws-sdk-message="[DEBUG: Request ec2metadata/GetMetadata Details:\n---[ REQUEST POST-SIGN ]-----------------------------\nGET /latest/meta-data/iam/security-credentials/ HTTP/1.1\r\nHost: 169.254.169.254\r\nUser-Agent: aws-sdk-go/1.25.38 (go1.13.4; linux; amd64)\r\nAccept-Encoding: gzip\r\n\r\n\n-----------------------------------------------------]"
DEBU[2019-12-02T16:01:15.192Z] aws-sdk-message="[DEBUG: Response ec2metadata/GetMetadata Details:\n---[ RESPONSE ]--------------------------------------\nHTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 38\r\nAccept-Ranges: none\r\nContent-Type: text/plain\r\nDate: Mon, 02 Dec 2019 16:01:15 GMT\r\nLast-Modified: Mon, 02 Dec 2019 15:55:34 GMT\r\nServer: EC2ws\r\n\r\n\n-----------------------------------------------------]"

I run this app without specifying AWS env keys nor with a shared profile.

[tyrken]

@pmalekn - They introduced the new EC2 metadata feature in v1.25.38 - and a backwards compatibility issue by setting the default hop limit to 1 - which means the replies get dropped while transiting the docker bridge network.

You have to increase the hop limit yourself or it just hit lengthy timeouts & retries before eventual fallback to the old method

[pmalekn]

@tyrken Ok... so you're probably referring to https://github.com/aws/aws-sdk-go/commit/7814a7f61bf93cb54d00a5f97918c5501f07d351#diff-68798fbeff74277f6e5c5ab6f1cf92c6R70454-R70460

Adding a snippet since the file is too big to show when linked service/ec2/api.go

// The metadata options for the instance.
type InstanceMetadataOptionsRequest struct {
    _ struct{} `type:"structure"`

    // This parameter enables or disables the HTTP metadata endpoint on your instances.
    // If the parameter is not specified, the default state is enabled.
    //
    // If you specify a value of disabled, you will not be able to access your instance
    // metadata.
    HttpEndpoint *string `type:"string" enum:"InstanceMetadataEndpointState"`

    // The desired HTTP PUT response hop limit for instance metadata requests. The
    // larger the number, the further instance metadata requests can travel.
    //
    // Default: 1
    //
    // Possible values: Integers from 1 to 64
    HttpPutResponseHopLimit *int64 `type:"integer"`

It then makes sense that it cannot reach the endpoint if I'm calling it from inside a docker container (because there's one more hop through docker bridge right?) or is my reasoning flawed?

How can I change this "globally" then? Or do I have to do it per request basis (that doesn't sound feasible)

[tyrken]

No global option I know of, though hoping AWS might see sense & implement something like https://github.com/aws/aws-sdk-go/issues/2980

In the mean time you can only stay on old version of aws-sdk or update all EC2 instances to increase the hop limit, e.g. with:

aws ec2 modify-instance-metadata-options --instance-id i-34215432543254235 --http-endpoint enabled --http-put-response-hop-limit 2

[alexd765]

Our problem is the same as described above.

aws ec2 modify-instance-metadata-options --instance-id i-34215432543254235 --http-endpoint enabled --http-put-response-hop-limit 2
is a temporary solution.

I really hope their will be a better solution in the future.
Running Go with this sdk in a docker container on an EC2 instance is one of the most common use cases of this sdk that I can think of. This really should just work out of the box.

[meastham]

I'm still experiencing this issue in v1.29.2, so it does not seem like #3066 fully solved it. Downgrading to v1.25.37 reduces the startup time of a Go server I run in a Docker container on EKS from minutes to ~1 second. Will there by any fix in the SDK for this issue? Changing the instance metadata is not an appealing workaround because it seems to not be possible to do this from Terraform.

[jasdel]

Thanks for the update @meastham could you provide more details, or example of how your app is using the SDK? Delay on the order of minutes seems very excessive. In the worst case the SDK shouldn't of experienced a delay larger than 20 seconds with regard to #3066

[meastham]

@jasdel Thanks for the response!

From an example log I just looked at it looks like the long running operations are:

• EC2Metadata::Region: 3 seconds
• s3manager.Downloader::Download: 1.45 minutes

The two operations use different AWS Sessions which is a little sloppy on our part. The S3 file being downloaded is small, <10KiB. I guess that function does multiple API calls under the hood that are somehow adding the delays together? Refetching the same file later on in the process takes only 37ms so it seems almost certainly related to initialization.

I can't share the exact code but should have some time next week to produce a reduced version if it would help you.

[vincentjorgensen]

increasing the hop limit to 2 works for us. Is there any risk to doing this in a production environment?

[philip-firstorder]

I have a delay of 3 seconds as of v1.29.24 when trying to create a new session using this code:

sess, err := session.NewSession(&aws.Config{
    Region: aws.String(region)},
)

I am using:

• Multiple Docker Container Environment in Elastic Beanstalk
• EC2 role
• t2.micro instance
• ECR docker image pushed by a Bitbucket Pipeline

Will revert to v1.25.19 until this is fixed, because manually increasing the hop limit is not an acceptable solution.

[dmegyesi]

@vincentjorgensen This article summarizes very well how this TTL thing works: https://aws.amazon.com/blogs/security/defense-in-depth-open-firewalls-reverse-proxies-ssrf-vulnerabilities-ec2-instance-metadata-service/ see the Protecting against open layer 3 firewalls and NATs section.

[particleflux]

Running on Fargate in ECS, this is not only slow but completely broken in latest SDK (v1.33.4 at time of testing). Errors with _could not find credentials configuration_.
Only downgrading to 1.25.37 resolves the issue, since the hop limit can not be configured for Fargate.

Tested with this https://github.com/particleflux/s3fetch/blob/master/s3fetch.go run directly in docker entrypoint.

[caleb15]

@alexd765 's solution worked for me - thanks Alex!

You can implement his solution in terraform like so:

resource "aws_instance" "your_ec2_instance_name" {
  params_go_here                     = var.blablabla

  metadata_options {
    # So docker can access ec2 metadata
    # see https://github.com/aws/aws-sdk-go/issues/2972
    http_put_response_hop_limit = 2
  }
}

Also note that it's not just go that runs into this problem - even just using curl as described in https://docs.aws.amazon.com/AWSEC2/latest/UserGuide/instancedata-data-retrieval.html results in a long delay.

[julvo]

Ran into the same problem using the AWS go SDK in an Elastic Beanstalk (EB) Docker environment, but didn't see a way to set http_put_response_hop_limit in EB without manipulating the EC2 instance directly.

Fixed (or rather sidestepped) it by setting AWS user credentials and default region as environment variables - hope it helps others in the same situation.

[xubofei1983]

We get same problem and walk-around works.