Receiving lots of HTTP timeouts from S3 client operation after update to latest version of SDK

[slinke-op]

Describe the bug

After updating software.amazon.awssdk:bom from 2.42.25 to latest (2.44.3) we're facing issue with HTTP timeouts on S3 client operations. I found #6866 which we observed in the past, but this happened very few times. This time, HTTP timeouts blew up our application and we had to roll back to 2.42.25.
We're using Java Temurin 25.0.2-10/x64 with Spring Boot 3.5.14. For the S3 operations we use amazon-s3-encryption-client-java 4.0.1.

Regression Issue

• Select this option if this issue appears to be a regression.

Expected Behavior

All HTTP operations made by S3 client complete successfully.

Current Behavior

Most of HTTP operations made by S3 client resulting in HTTP timeouts.
This is one example stacktrace of a head object request:

Caused by: software.amazon.awssdk.core.exception.SdkClientException: Unable to execute HTTP request: Timeout waiting for connection from pool (SDK Attempt Count: 1) at software.amazon.awssdk.core.exception.SdkClientException$BuilderImpl.build(SdkClientException.java:130) at software.amazon.awssdk.core.exception.SdkClientException$BuilderImpl.build(SdkClientException.java:95) at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.RetryableStageHelper.retryPolicyDisallowedRetryException(RetryableStageHelper.java:180) at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.execute(RetryableStage.java:86) at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.execute(RetryableStage.java:39) at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) at software.amazon.awssdk.core.internal.http.StreamManagingStage.execute(StreamManagingStage.java:53) at software.amazon.awssdk.core.internal.http.StreamManagingStage.execute(StreamManagingStage.java:35) at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.executeWithTimer(ApiCallTimeoutTrackingStage.java:82) at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:62) at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:43) at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage.execute(ApiCallMetricCollectionStage.java:50) at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage.execute(ApiCallMetricCollectionStage.java:32) at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:37) at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:26) at software.amazon.awssdk.core.internal.http.AmazonSyncHttpClient$RequestExecutionBuilderImpl.execute(AmazonSyncHttpClient.java:210) at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.invoke(BaseSyncClientHandler.java:103) at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.doExecute(BaseSyncClientHandler.java:173) at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.lambda$execute$1(BaseSyncClientHandler.java:80) at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.measureApiCallSuccess(BaseSyncClientHandler.java:182) at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.execute(BaseSyncClientHandler.java:74) at software.amazon.awssdk.core.client.handler.SdkSyncClientHandler.execute(SdkSyncClientHandler.java:45) at software.amazon.awssdk.awscore.client.handler.AwsSyncClientHandler.execute(AwsSyncClientHandler.java:53) at software.amazon.awssdk.services.s3.DefaultS3Client.headObject(DefaultS3Client.java:8303) at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:169) at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:119) at io.awspring.cloud.sqs.listener.adapter.CompositeInvocableHandler.invoke(CompositeInvocableHandler.java:82) at io.awspring.cloud.sqs.listener.adapter.AbstractMethodInvokingListenerAdapter.invokeHandler(AbstractMethodInvokingListenerAdapter.java:66) at io.awspring.cloud.sqs.listener.adapter.MessagingMessageListenerAdapter.onMessage(MessagingMessageListenerAdapter.java:46) at io.awspring.cloud.sqs.listener.AsyncComponentAdapters$AbstractThreadingComponentAdapter.lambda$withConsumerThreadLocalScope$3(AsyncComponentAdapters.java:206) ... 18 common frames omitted Caused by: org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:316) at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:282) at software.amazon.awssdk.http.apache.internal.conn.ClientConnectionRequestFactory$DelegatingConnectionRequest.get(ClientConnectionRequestFactory.java:92) at software.amazon.awssdk.http.apache.internal.conn.ClientConnectionRequestFactory$InstrumentedConnectionRequest.get(ClientConnectionRequestFactory.java:69) at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:190) at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186) at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56) at software.amazon.awssdk.http.apache.internal.impl.ApacheSdkHttpClient.execute(ApacheSdkHttpClient.java:72) at software.amazon.awssdk.http.apache.ApacheHttpClient.execute(ApacheHttpClient.java:261) at software.amazon.awssdk.http.apache.ApacheHttpClient.access$600(ApacheHttpClient.java:106) at software.amazon.awssdk.http.apache.ApacheHttpClient$1.call(ApacheHttpClient.java:238) at software.amazon.awssdk.http.apache.ApacheHttpClient$1.call(ApacheHttpClient.java:235) at software.amazon.awssdk.core.internal.util.MetricUtils.measureDurationUnsafe(MetricUtils.java:103) at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeHttpRequestStage.executeHttpRequest(MakeHttpRequestStage.java:92) at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeHttpRequestStage.execute(MakeHttpRequestStage.java:68) at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeHttpRequestStage.execute(MakeHttpRequestStage.java:50) at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:74) at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:43) at software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage.execute(TimeoutExceptionHandlingStage.java:79) at software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage.execute(TimeoutExceptionHandlingStage.java:41) at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage.execute(ApiCallAttemptMetricCollectionStage.java:58) at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage.execute(ApiCallAttemptMetricCollectionStage.java:41) at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.executeRequest(RetryableStage.java:106) at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.execute(RetryableStage.java:62) ... 54 common frames omitted

Reproduction Steps

var request = HeadObjectRequest.builder().bucket("bucketName").key("objectKey").build(); var versionId = s3Client.headObject(request).versionId();

Possible Solution

No response

Additional Information/Context

No response

AWS Java SDK version used

2.44.3

JDK version used

25.0.2-10

Operating System and version

gcr.io/distroless/java25-debian13

[debora-ito]

@slinke-op thank you for reaching out, and sorry you are getting bit by this.

This time, HTTP timeouts blew up our application and we had to roll back to 2.42.25.

• Does the exception happen with every request, or is it intermittent?
• Can you show your dependency tree, to make sure this is not a SDK version mismatch? mvn dependency:tree
• How the S3 client is created, can you share a sample code?

[RanVaknin]

Hi @slinke-op ,

I have some theories about why this was happening, but It's hard to say without knowing more about what came before these connection errors.

On top @debora-ito 's questions, can you please provide the follwoing info:

1. Your S3 client's configuration - specifically maxConnections, connectionAcquisitionTimeout values?
2. We would ideally get the SDK request/ response logs showing chain of events leading up to this. I understand that this might be difficult to get if it means upgrading and observing these in PROD. Is there a Beta environment you can try to reproduce this in to get logs from?
3. Were you seeing lots of 503 errors leading up to these connection errors?

Here is my main theory:

Last month I merged #6845 which was first shipped in version 2.43.1. That PR changed S3 Head* operations with a status code of 503 and Slow Down status message to be treated as Throttling errors. This behavior existed in our v1 SDK, and is technically the correct behavior. The main implication of throttling vs non-throttling 503's is the delay time between each retry. I'm not sure why exactly that would exhaust the connections in the pool, but from the version range you provided, this is the only change I found that is somewhat related.

I've written some tests to try and reproduce the reported behavior by simulating concurrent headObject calls against a mock server returning 503 Slow Down, but was not able to conclusively prove the connection pool exhaustion was a direct result of this longer delay.

If you have a Beta environment and can upgrade to 2.43.1, that would help us determine whether that is indeed the offending change.

Apologies for the inconvenience.
Thanks,
Ran~

[chris-mcc]

It looks like the old apache http client is being used

There is an old bug in the connection pool impls that can cause stuck threads in certain cases

I believe its really only seen when using virtual threads

So it might be helpful to to try the newer apache http5 client and ensure it's picking up the latest core and client releases.

(Also if using virtual threads upgrade to java 25.0.3+ they fixed a nasty virtual thread pinning bug)

[slinke-op]

Hi @debora-ito, @RanVaknin and @chris-mcc,
Thank you for your detailed—and, hopefully, helpful—responses! I have logged this issue internally as a ticket; therefore, either I or one of my colleagues will provide you with further information as soon as we begin processing it. I'll add information about the dependencies you mentioned to gradually step into the regression :)

[debora-ito]

@slinke-op any new findings you can share about the investigation?