Minimum TTL on instance profile credentials results in unstable connections to AWS resources

[ehm-93]

Describe the bug

Seems like commit 3f67bf74 introduced a minimum wait of 15 minutes before credentials are refreshed if credentials received from instance metadata expire in less than 15 minutes. This poses a problem as tokens received from instance metadata don't refresh when you request them, but refresh asynchronously in the background. When the token TTL is equal to this 15-minute refresh interval an app using the SDK will inevitably get into a state similar to the following:

1. 00:00 AWS magic refreshes instance metadata credentials
2. 00:03 The SDK fetches the token, sees it expires in less than 15 minutes, and schedules a refresh in 15 minutes
3. 00:10 AWS magic refreshes instance metadata credentials
4. 00:15 The SDK's token expires, all of my calls to DynamoDB are now failing ☹️
5. 00:18 The SDK fetches the token, sees it expires in less than 15 minutes, and schedules a refresh in 15 minutes
6. ...repeat forever!

The impact is more pronounced if the SDK fetches a token closer to expiry (eg token expires at 00:15 and is fetched at 00:14).

This boils down to differences between v2.17.158's HttpCredentialsProvider.getPrefetchTime(...) which scheduled tokens to be refreshed immediately if they expire in less than 15 minutes and v2.17.159's InstanceProfileCredentialsProvider.getPrefetchTime(...) which has the behavior described above. ☝️

Expected behavior

If instance metadata tokens are expired they should be refreshed immediately, if tokens expire in less than 15 minutes they should refresh before they expire

Current behavior

Instance metadata tokens which are expired or nearly expired are refreshed in 15 minutes even if they expire in less than 15 minutes

Steps to Reproduce

Deploy an SDK v2.17.159 app to an EC2 instance whose tokens' TTLs are the 15 minute minimum and try to use instance metadata credentials to access DynamoDB

Possible Solution

Return the old behavior of immediately refreshing expired tokens
Schedule soon-to-expire tokens to refresh before they expire

Context

No response

AWS Java SDK version used

v2.17.159

JDK version used

11

Operating System and version

Base image openjdk:11-jdk-slim

[millems]

That sounds very scary. Let me revert that feature in the next release until we can determine what's going on.

[millems]

@ehm-93 A few questions:

1. Do you have any "Failure encountered when attempting to refresh credentials" in your logs?
2. What mechanism are you using to configure the TTL to 15 minutes?

[ehm-93]

Here's the first suspicious warning when the app starts up:

{
  "ts": "2022-04-04T20:41:58.264Z",
  "logger": "software.amazon.awssdk.auth.credentials.InstanceProfileCredentialsProvider",
  "level": "WARN",
  "class": "software.amazon.awssdk.utils.Logger",
  "method": "warn",
  "file": "Logger.java",
  "line": 106,
  "thread": "main",
  "msg": "IMDS credential expiration has been extended due to an IMDS availability outage. A refresh of these credentials will be attempted again in 15 minutes."
}

Followed eventually by a storm of:

{
  "ts": "2022-04-04T20:56:04.798Z",
  "logger": "Proprietary!",
  "level": "ERROR",
  "class": "Proprietary!",
  "method": "Proprietary!",
  "file": "Proprietary!",
  "line": -1,
  "thread": "sdk-async-response-0-197",
  "stack": "vvv below vvv",
  "msg": "The security token included in the request is expired (Service: DynamoDb, Status Code: 400, Request ID: DBA8J1MT6841FTVO2NKVHJ08CNVV4KQNSO5AEMVJF66Q9ASUAAJG)"
}

Stack...

software.amazon.awssdk.services.dynamodb.model.DynamoDbException: The security token included in the request is expired (Service: DynamoDb, Status Code: 400, Request ID: DBA8J1MT6841FTVO2NKVHJ08CNVV4KQNSO5AEMVJF66Q9ASUAAJG)
	at software.amazon.awssdk.services.dynamodb.model.DynamoDbException$BuilderImpl.build(DynamoDbException.java:95)
	at software.amazon.awssdk.services.dynamodb.model.DynamoDbException$BuilderImpl.build(DynamoDbException.java:55)
	at software.amazon.awssdk.protocols.json.internal.unmarshall.AwsJsonProtocolErrorUnmarshaller.unmarshall(AwsJsonProtocolErrorUnmarshaller.java:89)
	at software.amazon.awssdk.protocols.json.internal.unmarshall.AwsJsonProtocolErrorUnmarshaller.handle(AwsJsonProtocolErrorUnmarshaller.java:63)
	at software.amazon.awssdk.protocols.json.internal.unmarshall.AwsJsonProtocolErrorUnmarshaller.handle(AwsJsonProtocolErrorUnmarshaller.java:42)
	at software.amazon.awssdk.core.http.MetricCollectingHttpResponseHandler.lambda$handle$0(MetricCollectingHttpResponseHandler.java:52)
	at software.amazon.awssdk.core.internal.util.MetricUtils.measureDurationUnsafe(MetricUtils.java:64)
	at software.amazon.awssdk.core.http.MetricCollectingHttpResponseHandler.handle(MetricCollectingHttpResponseHandler.java:52)
	at software.amazon.awssdk.core.internal.http.async.AsyncResponseHandler.lambda$prepare$0(AsyncResponseHandler.java:89)
	at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture.complete(Unknown Source)
	at software.amazon.awssdk.core.internal.http.async.AsyncResponseHandler$BaosSubscriber.onComplete(AsyncResponseHandler.java:132)
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler$DataCountingPublisher$1.onComplete(ResponseHandler.java:513)
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.runAndLogError(ResponseHandler.java:249)
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.access$600(ResponseHandler.java:74)
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler$PublisherAdapter$1.onComplete(ResponseHandler.java:370)
	at software.amazon.awssdk.http.nio.netty.internal.nrs.HandlerPublisher.publishMessage(HandlerPublisher.java:402)
	at software.amazon.awssdk.http.nio.netty.internal.nrs.HandlerPublisher.flushBuffer(HandlerPublisher.java:338)
	at software.amazon.awssdk.http.nio.netty.internal.nrs.HandlerPublisher.receivedDemand(HandlerPublisher.java:291)
	at software.amazon.awssdk.http.nio.netty.internal.nrs.HandlerPublisher.access$200(HandlerPublisher.java:61)
	at software.amazon.awssdk.http.nio.netty.internal.nrs.HandlerPublisher$ChannelSubscription$1.run(HandlerPublisher.java:495)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at java.base/java.lang.Thread.run(Unknown Source)

[ehm-93]

I'm just an app dev so a lot of this AWS internal stuff is magic to me. But I've chatted with a few members of devops gang and they've told me we don't do any configuration of the IMDS credential TTL and they're not sure if it even is configurable. It may just be hardcoded by AWS as 15 minutes.

[millems]

Are you seeing "IMDS credential expiration has been extended..." pretty much as soon as your application starts or after some time?

[ehm-93]

Both. Consistently when the app starts, then again after 15 minutes when the credentials get refreshed.

[ehm-93]

I imagine I'd see it in another 15 too but I'd have to leave the app dead in our test environment for 30 minutes. 🙂

[millems]

That's very odd. By all accounts, imds credentials should be valid for 6 hours at startup, but you're seeing under 15 minutes. I know sometimes people use custom imds implementations, backed by sts or something similar. I wonder whether that's happening here? If you're not sure, we might be able to find a command to run to test that theory.

For example, https://github.com/99designs/aws-vault usage might cause some of the symptoms you're observing.

[ehm-93]

I'm not sure if we're doing anything custom with IMDS but I can say our services run in containers in EKS and not directly on EC2 if that helps at all.

I want to be sure we're not confusing the IMDS session token, which is fetched here from http://169.254.169.254/latest/api/token and does have a 6 hour TTL (at least the SDK requests a 6 hour TTL), with IMDS credentials, which are fetched here from http://169.254.169.254/latest/meta-data/iam/security-credentials/{ instanceRole }. The credentials are the component which has the 15 minute TTL (in my environment at least). I can't find any AWS documentation specifying that the TTL is always 15 minutes but I did find this which says:

We make new credentials available at least five minutes before the expiration of the old credentials.

🤷

[millems]

I've checked with IMDS and we don't believe this should be able to happen with standard IMDS. Please tell me if you're absolutely sure you're using standard IMDS, because we can go deeper on your specific instance to see what's going on.

I'm guessing you might be doing something like kube2iam. If you are, it's something we should support regardless. I can make a change to behave better with those shorter credential durations.