Prevent possible race condition on IAM token expiry

[chlunde]

Describe the feature

We had some DB connections fail after when using this driver and IAM authentication. This was fixed by 2.1.2 and newer via #456 and #457.

But I don't think this code path should have triggered at all, because tokens should be refreshed in time.

In the logs, we still see a few "pam_authenticate failed: Permission denied" every hour. This will be very confusing when diagnosing other issues. I also expect

Use Case

No unnecessary reconnects, stable latency. No confusing log messages about expired token.

Proposed Solution

I would expect there to be a small grace period to prevent "TOCTTOU" race conditions, where the client code thinks it is valid when checking it, but the token is invalid when the server side receives and validates it.

This code uses exactly 900 seconds as a default. Subtracting somewhere between 2-30 seconds should be enough.

https://github.com/awslabs/aws-advanced-jdbc-wrapper/blob/708d8a240ef2cca9a7fc993f940688369374f26b/wrapper/src/main/java/software/amazon/jdbc/plugin/IamAuthConnectionPlugin.java#L53-L54

This should also improve P99 latencies.

You could also consider background refreshes, but I'm not sure if that's a good idea, it certainly adds complexity.

Other Information

No response

Acknowledgements

• I may be able to implement this feature request
• This feature might incur a breaking change

The AWS Advanced JDBC Driver version used

2.1.2+

JDK version used

17

Operating System and version

bottlerocket

[crystall-bitquill]

Hi @chlunde,

Thanks for reaching out and raising this issue.

We'll take a look at this and keep you updated as we investigate.

Thank you for your patience!

[davecramer]

@chlunde Interestingly enough when I tested how long an IAM token was valid for it was more like 20 minutes. Have you done any experiments around this ? I am very curious how you are getting these errors if this is really the case.

[chlunde]

@davecramer hi, after connecting the token is not re-validated, so maybe that's what you saw with 20+ minutes? You can keep using a connection for 20 minutes and more. I had a hunch that there might still be an issue when I checked the logs, as I have been involved in this kind of race condition a few times before. I have not done any experiment, but if you write a client that creates 10 new connections per second, I suspect you will run into this issue.

I also "dumped" my thoughts on this below, hope this helps.

900s?

I based my 900 seconds token life time, on the documentation and also this is what I see in use in practice:

aws rds generate-db-auth-token --hostname foo-db1.eu-north-1.amazonaws.com --port 5432 --username appuser

foo-db1.eu-north-1.amazonaws.com:5432/?Action=connect&DBUser=appuser&X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=ASIA...%2F20230828%2Feu-north-1%2Frds-db%2Faws4_request&X-Amz-Date=20230828T075446Z&X-Amz-Expires=900&X-Amz-Signed..

notice X-Amz-Expires=900.

I also see it hard coded here in the Java SDK:

https://github.com/aws/aws-sdk-java-v2/blob/f502f9f1e8a511cfae571adbb9390a3cf0c82f40/services/rds/src/main/java/software/amazon/awssdk/services/rds/DefaultRdsUtilities.java#L40-L41

Race timeline example - theory

So in theory, I think a race condition here is very possible, based on the code.

1. 10:00:00.000: client generates token using AWS STS, sets valid until 10:15.00.010 (but that is a lie, it expires 10:15.00.005, the time STS generated the token)
2. 10:14.59.990: client reuses token as is is valid
3. 10:15.00.010: server receives token. Server sends to PAM module. PAM module sends a new HTTP-request to rdsauthproxy sidecar on RDS. Notice this is a JVM which might be "cold" and introduce extra latency. 70ms latency here is normal, 200ms is not unheard of.
4. 10.15.00.060: rdsauthproxy on RDS receives and processes token. Is has expired.

Real, observed errors in prod

I also verified that we see such errors by downloading logs from the RDS console and check the logs:

grep 'pam_authenticate failed: Permission denied' postgresql.log.2023-08-25-07*
I see three such issues this morning for an application I checked.

Of course, it might be the case that we have such log entries due to another issue.

Is this a misconfigured client?

Since we run into this race condition so often, I wondered if that could mean this application I checked did something wrong. I checked prometheus to get the number of new JDBC connections established, and it does not create a lot of connections:

But as you can see, it refreshes connections after about 15 minutes, and then there are N new connections refreshed (the whole pool), where each of them might trigger the race.

Summary, possible fixes and issues

I see there are at least two race conditions in the code:

• Network latency between token generation and expiry time calculation. This can be fixed by getting Instant.now().plus(tokenExpirationSec, ChronoUnit.SECONDS) before calling STS.
• Network latency between validity check and the right component in AWS receiving the token. This can only be fixed by adding slack to the validity check.

[chlunde]

An additional point: We're running on EKS using IRSA. To generate STS tokens, this introduces another roundtrip to STS via AssumeRoleWithWebIdentity. To avoid this roundtrip for each call, you must always reuse the AwsCredentialsProvider. We saw significant improvements when doing this in our in-house JDBC.

[crystall-bitquill]

Hi @chlunde,

To update you, I tried to reproduce this issue by getting 10 new connections every second with the default IAM plugin properties. This was run on a loop for several hours, but I wasn't able to trigger any authentication errors. However, I have opened a PR (#706) to implement your suggestions. These changes are now available in our latest snapshot build, could you kindly check it out and let us know if this helps prevent the errors you've been experiencing?

Thank you!

[crystall-bitquill]

Hi @chlunde,

I wanted to check in and see if the changes helped prevent the authentication errors you've been getting. If there are no further updates on this ticket in the next few days, it will be closed. However, if you have any other questions or concerns please feel free to reopen this issue or to create a new one.

Thank you!