Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

DynamoDB timeouts causing apache ConnectionClosedException #5753

Open
1 task
zakerf opened this issue Dec 16, 2024 · 6 comments
Open
1 task

DynamoDB timeouts causing apache ConnectionClosedException #5753

zakerf opened this issue Dec 16, 2024 · 6 comments
Assignees
@debora-ito
Labels
bug This issue is a bug. p2 This is a standard priority issue response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 10 days.

Comments

@zakerf
Copy link

zakerf commented Dec 16, 2024

Describe the bug

We use the DynamoDbEnhancedClient to do batchGetItems with some stricter timeout settings than normal, it seems that is causing org.apache.http.ConnectionClosedException to be thrown.

Regression Issue

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

Expected Behavior

An ApiCallTimeoutException when an API call fails

Current Behavior

We get the following stacktrace:

logger: software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage

Failed to close the response stream
org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 52,271; received: 3,818)
at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:178)
at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:198)
at org.apache.http.impl.io.ContentLengthInputStream.close(ContentLengthInputStream.java:101)
at org.apache.http.impl.execchain.ResponseEntityProxy.streamClosed(ResponseEntityProxy.java:142)
at org.apache.http.conn.EofSensorInputStream.checkClose(EofSensorInputStream.java:228)
at org.apache.http.conn.EofSensorInputStream.close(EofSensorInputStream.java:172)
at java.base/java.io.FilterInputStream.close(Unknown Source)
at software.amazon.awssdk.utils.FunctionalUtils.runAndLogError(FunctionalUtils.java:40)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.lambda$handleInterruptedException$0(ApiCallAttemptTimeoutTrackingStage.java:135)
at java.base/java.util.Optional.ifPresent(Unknown Source)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.handleInterruptedException(ApiCallAttemptTimeoutTrackingStage.java:135)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.translatePipelineException(ApiCallAttemptTimeoutTrackingStage.java:107)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:91)
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:55)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage.execute(ApiCallAttemptMetricCollectionStage.java:39)
at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage2.executeRequest(RetryableStage2.java:93)
at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage2.execute(RetryableStage2.java:56)
at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage2.execute(RetryableStage2.java:36)
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.dynamodb.DefaultDynamoDbClient.batchGetItem(DefaultDynamoDbClient.java:494)
at software.amazon.awssdk.services.dynamodb.paginators.BatchGetItemIterable$BatchGetItemResponseFetcher.nextPage(BatchGetItemIterable.java:111)
at software.amazon.awssdk.services.dynamodb.paginators.BatchGetItemIterable$BatchGetItemResponseFetcher.nextPage(BatchGetItemIterable.java:102)
at software.amazon.awssdk.core.pagination.sync.PaginatedResponsesIterator.next(PaginatedResponsesIterator.java:58)
at software.amazon.awssdk.enhanced.dynamodb.internal.TransformIterator.next(TransformIterator.java:44)
at software.amazon.awssdk.core.pagination.sync.PaginatedItemsIterable$ItemsIterator.(PaginatedItemsIterable.java:58)
at software.amazon.awssdk.core.pagination.sync.PaginatedItemsIterable.iterator(PaginatedItemsIterable.java:48)
at java.base/java.lang.Iterable.spliterator(Unknown Source)
at software.amazon.awssdk.core.pagination.sync.SdkIterable.stream(SdkIterable.java:34)
at
at java.base/java.util.stream.ReferencePipeline$7$1.accept(Unknown Source)
at java.base/java.util.Iterator.forEachRemaining(Unknown Source)
at java.base/java.util.Spliterators$IteratorSpliterator.forEachRemaining(Unknown Source)
at java.base/java.util.stream.AbstractPipeline.copyInto(Unknown Source)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source)
at java.base/java.util.stream.AbstractPipeline.evaluate(Unknown Source)
at java.base/java.util.stream.AbstractPipeline.evaluateToArrayNode(Unknown Source)
at java.base/java.util.stream.ReferencePipeline.toArray(Unknown Source)
at java.base/java.util.stream.ReferencePipeline.toArray(Unknown Source)
at java.base/java.util.stream.ReferencePipeline.toList(Unknown Source)
at
at
at
at
at reactor.core.publisher.MonoCallable$MonoCallableSubscription.request(MonoCallable.java:137)
at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.trySchedule(MonoSubscribeOn.java:189)
at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onSubscribe(MonoSubscribeOn.java:134)
at com.dynatrace.agent.introspection.reactor3.TracingReactorSubscriber.onSubscribe(TracingReactorSubscriber.java:30)
at reactor.core.publisher.MonoCallable.subscribe(MonoCallable.java:48)
at reactor.core.publisher.Mono.subscribe(Mono.java:4576)
at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.run(MonoSubscribeOn.java:126)
at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:84)
at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:37)
at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.base/java.lang.Thread.run(Unknown Source)

Reproduction Steps

This is how we build up our client:

DynamoDbClient.builder()
                .overrideConfiguration(clientOverride -> clientOverride
                        .apiCallAttemptTimeout(Duration.ofMillis(100))
                        .apiCallTimeout(Duration.ofMillis(500))
                        .retryStrategy(retry ->
                                AwsRetryStrategy
                                        .defaultRetryStrategy()
                                        .toBuilder()
                                        .maxAttempts(3)
                                        .backoffStrategy(BackoffStrategy.exponentialDelayHalfJitter(Duration.ofMillis(10), Duration.ofMillis(100)))
                        ))
                .build();

I assume it has something to do with timeouts, not sure how you can easily reproduce that

Possible Solution

No response

Additional Information/Context

No response

AWS Java SDK version used

2.29.27

JDK version used

openjdk 21.0.5 2024-10-15 LTS OpenJDK Runtime Environment (build 21.0.5+11-LTS) OpenJDK 64-Bit Server VM (build 21.0.5+11-LTS, mixed mode, sharing)

Operating System and version

Ubuntu 22.04.5 LTS
@zakerf zakerf added bug This issue is a bug. needs-triage This issue or PR still needs to be triaged. labels Dec 16, 2024
@zhy2002
Copy link

zhy2002 commented Dec 20, 2024

seeing the same problem when sending multiple concurrent queries for different partition keys

@debora-ito
Copy link
Member

@zhy2002 the SDK is not at the top of your stacktrace, so it's possible that ApiCallTimeoutException is being "swallowed" by EofSensorInputStream or ContentLengthInputStream:

org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 52,271; received: 3,818)
	at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:178)
	at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:198)
	at org.apache.http.impl.io.ContentLengthInputStream.close(ContentLengthInputStream.java:101)
	at org.apache.http.impl.execchain.ResponseEntityProxy.streamClosed(ResponseEntityProxy.java:142)
	at org.apache.http.conn.EofSensorInputStream.checkClose(EofSensorInputStream.java:228)
	at org.apache.http.conn.EofSensorInputStream.close(EofSensorInputStream.java:172)
	at java.base/java.io.FilterInputStream.close(Unknown Source)
	at software.amazon.awssdk.utils.FunctionalUtils.runAndLogError(FunctionalUtils.java:40)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.lambda$handleInterruptedException$0(ApiCallAttemptTimeoutTrackingStage.java:135)
	at java.base/java.util.Optional.ifPresent(Unknown Source)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.handleInterruptedException(ApiCallAttemptTimeoutTrackingStage.java:135)
...

I did a test run with a simple DynamoDB request call (no ContentLengthInputStream and no EofSensorInputStream were used) and ApiCallTimeoutException is thrown:

        DynamoDbClient client = DynamoDbClient.builder()
                .overrideConfiguration(clientOverride -> clientOverride
                        .apiCallAttemptTimeout(Duration.ofMillis(500))
                        .apiCallTimeout(Duration.ofMillis(100))
                )
                .build();

        client.listTables();
software.amazon.awssdk.core.exception.ApiCallTimeoutException: Client execution did not complete before the specified timeout configuration: 100 millis

	at software.amazon.awssdk.core.exception.ApiCallTimeoutException$BuilderImpl.build(ApiCallTimeoutException.java:97)
	at software.amazon.awssdk.core.exception.ApiCallTimeoutException.create(ApiCallTimeoutException.java:38)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.generateApiCallTimeoutException(ApiCallTimeoutTrackingStage.java:156)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.handleInterruptedException(ApiCallTimeoutTrackingStage.java:144)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.translatePipelineException(ApiCallTimeoutTrackingStage.java:109)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:64)
...

Does ApiCallTimeoutException shows up as "Caused by" somewhere in your stacktrace?

@debora-ito debora-ito added response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 10 days. p2 This is a standard priority issue and removed needs-triage This issue or PR still needs to be triaged. labels Dec 28, 2024
@debora-ito debora-ito self-assigned this Dec 28, 2024
@zakerf
Copy link
Author

zakerf commented Dec 30, 2024

We have separate stacktraces for when we get ApiCallTimeoutException, see an example below:

software.amazon.awssdk.core.exception.ApiCallTimeoutException: Client execution did not complete before the specified timeout configuration: 500 millis
		at software.amazon.awssdk.core.exception.ApiCallTimeoutException$BuilderImpl.build(ApiCallTimeoutException.java:97)
		at software.amazon.awssdk.core.exception.ApiCallTimeoutException.create(ApiCallTimeoutException.java:38)
		at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.generateApiCallTimeoutException(ApiCallTimeoutTrackingStage.java:156)
		at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.handleInterruptedException(ApiCallTimeoutTrackingStage.java:144)
		at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.translatePipelineException(ApiCallTimeoutTrackingStage.java:109)
		at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:64)
		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.dynamodb.DefaultDynamoDbClient.batchGetItem(DefaultDynamoDbClient.java:494)
		at software.amazon.awssdk.services.dynamodb.paginators.BatchGetItemIterable$BatchGetItemResponseFetcher.nextPage(BatchGetItemIterable.java:111)
		at software.amazon.awssdk.services.dynamodb.paginators.BatchGetItemIterable$BatchGetItemResponseFetcher.nextPage(BatchGetItemIterable.java:102)
		at software.amazon.awssdk.core.pagination.sync.PaginatedResponsesIterator.next(PaginatedResponsesIterator.java:58)
		at software.amazon.awssdk.enhanced.dynamodb.internal.TransformIterator.next(TransformIterator.java:44)
		at software.amazon.awssdk.core.pagination.sync.PaginatedItemsIterable$ItemsIterator.<init>(PaginatedItemsIterable.java:58)
		at software.amazon.awssdk.core.pagination.sync.PaginatedItemsIterable.iterator(PaginatedItemsIterable.java:48)
		at java.base/java.lang.Iterable.spliterator(Unknown Source)
		at software.amazon.awssdk.core.pagination.sync.SdkIterable.stream(SdkIterable.java:34)

@github-actions github-actions bot removed the response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 10 days. label Dec 30, 2024
@debora-ito
Copy link
Member

Yes, that is what I would expect. Let us know if you have any other question.

@debora-ito debora-ito added the response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 10 days. label Dec 30, 2024
@zakerf
Copy link
Author

zakerf commented Dec 31, 2024

Well yes I sometimes get this stacktrace but more often I get the ConnectionClosedException and my question is why that happens. The exception and the stacktrace indicates to me that either the SDK or DynamoDB is doing something wrong

@github-actions github-actions bot removed the response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 10 days. label Dec 31, 2024
@debora-ito
Copy link
Member

Can you provide a self-contained code example I can use to repro? Please include how you are reading the BatchGetItem response.

@debora-ito debora-ito added the response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 10 days. label Dec 31, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@debora-ito debora-ito

Labels
bug This issue is a bug. p2 This is a standard priority issue response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 10 days.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@debora-ito @zhy2002 @zakerf