S3AsyncClient: stuck thread if upload failed #4801

chaykin · 2023-12-22T06:30:37Z

Describe the bug

I upload content by S3AsyncClient#putObject, it automatically splits to chunks, but for one of these, S3-server response error code 500. After this, CompletableFuture never completes (of fails) and, therefore, calling thread is stuck

Expected Behavior

CompletableFuture completes with exception

Current Behavior

Thread is stuck.

Reproduction Steps

Create client:

var client = S3AsyncClient.builder()
		.httpClientBuilder(
			AwsCrtAsyncHttpClient.builder()
				.connectionTimeout(Duration.ofSeconds(3))
				.maxConcurrency(32))
		.forcePathStyle(true)
		.endpointOverride(URL)
		.credentialsProvider(createCredentialsProvider())
		.region(EU_SOUTH_2)
		.multipartEnabled(true)
		.multipartConfiguration(b -> b.minimumPartSizeInBytes(16 * 1024L * 1024L))
		.build();

Uploading content:

String key = UUID.randomUUID().toString();
var request = PutObjectRequest.builder().bucket("ngcp").key(key).build();
var body = AsyncRequestBody.forBlockingInputStream(null);

var future = client.putObject(request, body);
try (InputStream in = createInputStream()) {
	body.writeInputStream(in);
}

future.join();

Result (omitted) log:

2023-12-22 11:00:55 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=POST, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, User-Agent], queryParameters=[uploads])
2023-12-22 11:00:55 [Thread-7] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:00:55 [sdk-async-response-0-17] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:00:55 [sdk-async-response-0-17] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:00:55 [sdk-async-response-0-17] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
...
2023-12-22 11:01:12 [Thread-11] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:01:12 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:01:12 [Thread-8] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:01:12 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:01:13 [Thread-9] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
...
2023-12-22 11:02:24 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:24 [Thread-10] DEBUG software.amazon.awssdk.request:85 - Received failed response: 500, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:24 [sdk-async-response-0-42] DEBUG software.amazon.awssdk.request:96 - Retryable error detected. Will retry in 47ms. Request attempt number 2
software.amazon.awssdk.services.s3.model.S3Exception: We encountered an internal error. Please try again. (Service: S3, Status Code: 500, Request ID: DpFbkwRcow)
	at software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handleErrorResponse(AwsXmlPredicatedResponseHandler.java:156) ~[aws-xml-protocol-2.21.32.jar:?]
	at software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handleResponse(AwsXmlPredicatedResponseHandler.java:108) ~[aws-xml-protocol-2.21.32.jar:?]
	at software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handle(AwsXmlPredicatedResponseHandler.java:85) ~[aws-xml-protocol-2.21.32.jar:?]
	at software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handle(AwsXmlPredicatedResponseHandler.java:43) ~[aws-xml-protocol-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.handler.BaseClientHandler.lambda$successTransformationResponseHandler$7(BaseClientHandler.java:279) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.http.async.AsyncResponseHandler.lambda$prepare$0(AsyncResponseHandler.java:92) ~[sdk-core-2.21.32.jar:?]
	at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1150) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147) ~[?:?]
	at software.amazon.awssdk.core.internal.http.async.AsyncResponseHandler$BaosSubscriber.onComplete(AsyncResponseHandler.java:135) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.utils.async.SimplePublisher.doProcessQueue(SimplePublisher.java:275) ~[utils-2.21.32.jar:?]
	at software.amazon.awssdk.utils.async.SimplePublisher.processEventQueue(SimplePublisher.java:224) ~[utils-2.21.32.jar:?]
	at software.amazon.awssdk.utils.async.SimplePublisher.complete(SimplePublisher.java:157) ~[utils-2.21.32.jar:?]
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.onSuccessfulResponseComplete(CrtResponseAdapter.java:113) ~[aws-crt-client-2.21.32.jar:?]
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.onResponseComplete(CrtResponseAdapter.java:106) ~[aws-crt-client-2.21.32.jar:?]
	at software.amazon.awssdk.crt.http.HttpStreamResponseHandlerNativeAdapter.onResponseComplete(HttpStreamResponseHandlerNativeAdapter.java:58) ~[aws-crt-0.28.9.jar:0.28.9]
2023-12-22 11:02:24 [sdk-ScheduledExecutor-1-0] DEBUG software.amazon.awssdk.request:85 - Retrying Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:24 [Thread-6] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:24 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:24 [Thread-10] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:24 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:25 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:26 [Thread-6] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:27 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:27 [Thread-6] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
software.amazon.awssdk.core.exception.NonRetryableException: A retry was attempted, but AsyncRequestBody.split does not support retries.
	at software.amazon.awssdk.core.exception.NonRetryableException$BuilderImpl.build(NonRetryableException.java:109)
	at software.amazon.awssdk.core.exception.NonRetryableException.create(NonRetryableException.java:49)
	at software.amazon.awssdk.core.internal.async.SplittingPublisher$SplittingSubscriber$DownstreamBody.subscribe(SplittingPublisher.java:295)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage$SdkHttpContentPublisherAdapter.subscribe(MakeAsyncHttpRequestStage.java:264)
	at software.amazon.awssdk.http.crt.internal.request.CrtRequestBodyAdapter.<init>(CrtRequestBodyAdapter.java:33)
	at software.amazon.awssdk.http.crt.internal.request.CrtRequestAdapter.toCrtRequest(CrtRequestAdapter.java:55)
	at software.amazon.awssdk.http.crt.internal.CrtRequestExecutor.executeRequest(CrtRequestExecutor.java:113)
	at software.amazon.awssdk.http.crt.internal.CrtRequestExecutor.lambda$execute$0(CrtRequestExecutor.java:88)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
	at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
	at software.amazon.awssdk.crt.http.HttpClientConnection.onConnectionAcquired(HttpClientConnection.java:124)
	at software.amazon.awssdk.crt.http.HttpClientConnection.httpClientConnectionReleaseManaged(Native Method)
	at software.amazon.awssdk.crt.http.HttpClientConnection.releaseNativeHandle(HttpClientConnection.java:92)
	at software.amazon.awssdk.crt.CrtResource.release(CrtResource.java:219)
	at software.amazon.awssdk.crt.CrtResource.decRef(CrtResource.java:295)
	at software.amazon.awssdk.crt.CrtResource.close(CrtResource.java:277)
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.lambda$onSuccessfulResponseComplete$1(CrtResponseAdapter.java:123)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:887)
	at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2325)
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.onSuccessfulResponseComplete(CrtResponseAdapter.java:113)
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.onResponseComplete(CrtResponseAdapter.java:106)
	at software.amazon.awssdk.crt.http.HttpStreamResponseHandlerNativeAdapter.onResponseComplete(HttpStreamResponseHandlerNativeAdapter.java:58)
2023-12-22 11:02:27 [sdk-async-response-0-41] DEBUG software.amazon.awssdk.request:96 - Retryable error detected. Will retry in 45ms. Request attempt number 3
software.amazon.awssdk.core.exception.SdkClientException: Unable to execute HTTP request: A callback has reported failure.
	at software.amazon.awssdk.core.exception.SdkClientException$BuilderImpl.build(SdkClientException.java:111) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.exception.SdkClientException.create(SdkClientException.java:47) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.RetryableStageHelper.setLastException(RetryableStageHelper.java:223) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.RetryableStageHelper.setLastException(RetryableStageHelper.java:218) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.maybeRetryExecute(AsyncRetryableStage.java:182) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.lambda$attemptExecute$1(AsyncRetryableStage.java:159) ~[sdk-core-2.21.32.jar:?]
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162) ~[?:?]
	at software.amazon.awssdk.utils.CompletableFutureUtils.lambda$forwardExceptionTo$0(CompletableFutureUtils.java:79) ~[utils-2.21.32.jar:?]
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162) ~[?:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage.lambda$execute$0(MakeAsyncHttpRequestStage.java:103) ~[sdk-core-2.21.32.jar:?]
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162) ~[?:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage.completeResponseFuture(MakeAsyncHttpRequestStage.java:240) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage.lambda$executeHttpRequest$3(MakeAsyncHttpRequestStage.java:163) ~[sdk-core-2.21.32.jar:?]
	at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:934) [?:?]
	at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:911) [?:?]
	at java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:482) [?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.base/java.lang.Thread.run(Thread.java:833) [?:?]
Caused by: software.amazon.awssdk.crt.http.HttpException: A callback has reported failure.
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.onResponseComplete(CrtResponseAdapter.java:108) ~[aws-crt-client-2.21.32.jar:?]
	at software.amazon.awssdk.crt.http.HttpStreamResponseHandlerNativeAdapter.onResponseComplete(HttpStreamResponseHandlerNativeAdapter.java:58) ~[aws-crt-0.28.9.jar:0.28.9]
2023-12-22 11:02:27 [sdk-ScheduledExecutor-1-0] DEBUG software.amazon.awssdk.request:85 - Retrying Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:27 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:28 [Thread-5] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:28 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:29 [Thread-11] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:29 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:31 [Thread-5] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:31 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:32 [Thread-11] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
software.amazon.awssdk.core.exception.NonRetryableException: A retry was attempted, but AsyncRequestBody.split does not support retries.
	at software.amazon.awssdk.core.exception.NonRetryableException$BuilderImpl.build(NonRetryableException.java:109)
	at software.amazon.awssdk.core.exception.NonRetryableException.create(NonRetryableException.java:49)
	at software.amazon.awssdk.core.internal.async.SplittingPublisher$SplittingSubscriber$DownstreamBody.subscribe(SplittingPublisher.java:295)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage$SdkHttpContentPublisherAdapter.subscribe(MakeAsyncHttpRequestStage.java:264)
	at software.amazon.awssdk.http.crt.internal.request.CrtRequestBodyAdapter.<init>(CrtRequestBodyAdapter.java:33)
	at software.amazon.awssdk.http.crt.internal.request.CrtRequestAdapter.toCrtRequest(CrtRequestAdapter.java:55)
	at software.amazon.awssdk.http.crt.internal.CrtRequestExecutor.executeRequest(CrtRequestExecutor.java:113)
	at software.amazon.awssdk.http.crt.internal.CrtRequestExecutor.lambda$execute$0(CrtRequestExecutor.java:88)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
	at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
	at software.amazon.awssdk.crt.http.HttpClientConnection.onConnectionAcquired(HttpClientConnection.java:124)
	at software.amazon.awssdk.crt.http.HttpClientConnection.httpClientConnectionReleaseManaged(Native Method)
	at software.amazon.awssdk.crt.http.HttpClientConnection.releaseNativeHandle(HttpClientConnection.java:92)
	at software.amazon.awssdk.crt.CrtResource.release(CrtResource.java:219)
	at software.amazon.awssdk.crt.CrtResource.decRef(CrtResource.java:295)
	at software.amazon.awssdk.crt.CrtResource.close(CrtResource.java:277)
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.lambda$onSuccessfulResponseComplete$1(CrtResponseAdapter.java:123)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:887)
	at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2325)
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.onSuccessfulResponseComplete(CrtResponseAdapter.java:113)
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.onResponseComplete(CrtResponseAdapter.java:106)
	at software.amazon.awssdk.crt.http.HttpStreamResponseHandlerNativeAdapter.onResponseComplete(HttpStreamResponseHandlerNativeAdapter.java:58)
2023-12-22 11:02:32 [sdk-async-response-0-44] DEBUG software.amazon.awssdk.request:96 - Retryable error detected. Will retry in 334ms. Request attempt number 4
software.amazon.awssdk.core.exception.SdkClientException: Unable to execute HTTP request: A callback has reported failure.
	at software.amazon.awssdk.core.exception.SdkClientException$BuilderImpl.build(SdkClientException.java:111) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.exception.SdkClientException.create(SdkClientException.java:47) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.RetryableStageHelper.setLastException(RetryableStageHelper.java:223) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.RetryableStageHelper.setLastException(RetryableStageHelper.java:218) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.maybeRetryExecute(AsyncRetryableStage.java:182) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.lambda$attemptExecute$1(AsyncRetryableStage.java:159) ~[sdk-core-2.21.32.jar:?]
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162) ~[?:?]
	at software.amazon.awssdk.utils.CompletableFutureUtils.lambda$forwardExceptionTo$0(CompletableFutureUtils.java:79) ~[utils-2.21.32.jar:?]
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162) ~[?:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage.lambda$execute$0(MakeAsyncHttpRequestStage.java:103) ~[sdk-core-2.21.32.jar:?]
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162) ~[?:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage.completeResponseFuture(MakeAsyncHttpRequestStage.java:240) ~[sdk-core-2.21.32.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage.lambda$executeHttpRequest$3(MakeAsyncHttpRequestStage.java:163) ~[sdk-core-2.21.32.jar:?]
	at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:934) [?:?]
	at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:911) [?:?]
	at java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:482) [?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.base/java.lang.Thread.run(Thread.java:833) [?:?]
Caused by: software.amazon.awssdk.crt.http.HttpException: A callback has reported failure.
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.onResponseComplete(CrtResponseAdapter.java:108) ~[aws-crt-client-2.21.32.jar:?]
	at software.amazon.awssdk.crt.http.HttpStreamResponseHandlerNativeAdapter.onResponseComplete(HttpStreamResponseHandlerNativeAdapter.java:58) ~[aws-crt-0.28.9.jar:0.28.9]
2023-12-22 11:02:32 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:32 [Thread-9] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:32 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:32 [sdk-ScheduledExecutor-1-1] DEBUG software.amazon.awssdk.request:85 - Retrying Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:36 [Thread-8] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:36 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:36 [Thread-8] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:36 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:37 [Thread-8] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:37 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:37 [Thread-4] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:37 [Test worker] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, Expect, User-Agent], queryParameters=[partNumber, uploadId])
2023-12-22 11:02:39 [Thread-7] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
software.amazon.awssdk.core.exception.NonRetryableException: A retry was attempted, but AsyncRequestBody.split does not support retries.
	at software.amazon.awssdk.core.exception.NonRetryableException$BuilderImpl.build(NonRetryableException.java:109)
	at software.amazon.awssdk.core.exception.NonRetryableException.create(NonRetryableException.java:49)
	at software.amazon.awssdk.core.internal.async.SplittingPublisher$SplittingSubscriber$DownstreamBody.subscribe(SplittingPublisher.java:295)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage$SdkHttpContentPublisherAdapter.subscribe(MakeAsyncHttpRequestStage.java:264)
	at software.amazon.awssdk.http.crt.internal.request.CrtRequestBodyAdapter.<init>(CrtRequestBodyAdapter.java:33)
	at software.amazon.awssdk.http.crt.internal.request.CrtRequestAdapter.toCrtRequest(CrtRequestAdapter.java:55)
	at software.amazon.awssdk.http.crt.internal.CrtRequestExecutor.executeRequest(CrtRequestExecutor.java:113)
	at software.amazon.awssdk.http.crt.internal.CrtRequestExecutor.lambda$execute$0(CrtRequestExecutor.java:88)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
	at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
	at software.amazon.awssdk.crt.http.HttpClientConnection.onConnectionAcquired(HttpClientConnection.java:124)
	at software.amazon.awssdk.crt.http.HttpClientConnection.httpClientConnectionReleaseManaged(Native Method)
	at software.amazon.awssdk.crt.http.HttpClientConnection.releaseNativeHandle(HttpClientConnection.java:92)
	at software.amazon.awssdk.crt.CrtResource.release(CrtResource.java:219)
	at software.amazon.awssdk.crt.CrtResource.decRef(CrtResource.java:295)
	at software.amazon.awssdk.crt.CrtResource.close(CrtResource.java:277)
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.lambda$onSuccessfulResponseComplete$1(CrtResponseAdapter.java:123)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:887)
	at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2325)
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.onSuccessfulResponseComplete(CrtResponseAdapter.java:113)
	at software.amazon.awssdk.http.crt.internal.response.CrtResponseAdapter.onResponseComplete(CrtResponseAdapter.java:106)
	at software.amazon.awssdk.crt.http.HttpStreamResponseHandlerNativeAdapter.onResponseComplete(HttpStreamResponseHandlerNativeAdapter.java:58)
2023-12-22 11:02:39 [sdk-async-response-0-43] DEBUG software.amazon.awssdk.request:85 - Sending Request: DefaultSdkHttpFullRequest(httpMethod=DELETE, protocol=https, host=hb.ru-msk.vkcs.cloud, encodedPath=/ngcp/b12f0d94-43f9-48d6-a43f-411c62f9f204, headers=[amz-sdk-invocation-id, User-Agent], queryParameters=[uploadId])
2023-12-22 11:02:39 [Thread-7] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:39 [Thread-11] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:39 [Thread-9] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:40 [Thread-11] DEBUG software.amazon.awssdk.request:85 - Received successful response: 200, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:40 [Thread-11] DEBUG software.amazon.awssdk.request:85 - Received successful response: 204, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:41 [Thread-7] DEBUG software.amazon.awssdk.request:85 - Received failed response: 404, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:41 [Thread-6] DEBUG software.amazon.awssdk.request:85 - Received failed response: 404, Request ID: not available, Extended Request ID: not available
2023-12-22 11:02:42 [Thread-5] DEBUG software.amazon.awssdk.request:85 - Received failed response: 404, Request ID: not available, Extended Request ID: not available
...
2023-12-22 11:02:51 [Thread-11] DEBUG software.amazon.awssdk.request:85 - Received failed response: 404, Request ID: not available, Extended Request ID: not available

Full log: upload.log
Thread dump: s3-thread-dump.log

Possible Solution

No response

Additional Information/Context

No response

AWS Java SDK version used

2.21.32

JDK version used

java version "17.0.6" 2023-01-17 LTS
Java(TM) SE Runtime Environment (build 17.0.6+9-LTS-190)
Java HotSpot(TM) 64-Bit Server VM (build 17.0.6+9-LTS-190, mixed mode, sharing)

Operating System and version

Ubuntu 22.04.3 LTS

The text was updated successfully, but these errors were encountered:

chaykin · 2023-12-22T09:37:36Z

After some debugging, I found out this:

CompletableFuture, returned by client#putObject is in correct state (isDone=true, isCompletedExceptionally=true)
Calling thread blocked at body.writeInputStream method

chaykin · 2024-01-05T15:05:33Z

Let's see at UploadWithUnknownContentLengthHelper.UnknownContentLengthAsyncRequestBodySubscriber#onSubscribe:

...
returnFuture.whenComplete((r, t) -> {
	if (t != null) {
		s.cancel();
		multipartUploadHelper.cancelingOtherOngoingRequests(futures, t);
	}
});

Here method Subscription#cancel invoked on s. And s is SimplePublisher.SubscriptionImpl, coming from SplittingPublisher.downstreamPublisher field. So, downstreamPublisher cancelling, if something went wrong. But SplittingPublisher has another field - upstreamPublisher and it state not changes. It lead us to stuck calling thread... I'm not so familiar with code and Publisher/Subscriber/Subscription conceptions, but it seems, upstreamPublisher needs cancel as well (at least with BlockingInputStreamAsyncRequestBody and unknown length).

So, I suggest:

Test project to reproduce (some kind of) this situation - https://github.com/chaykin/s3-sdk-test
Solution (most likely quck dirty hack) - chaykin@a85a651

debora-ito · 2024-01-24T20:23:14Z

@chaykin apologies for the long silence.

We made some changes recently in the CRT client connection handling (#4833, #4825, #4839), can you test a more recent version and confirm if you still see the issue? Just want to make sure it's not fixed in a latest version before start investigating.

The latest version of the SDK is 2.23.10 as of today.

chaykin · 2024-01-25T10:59:32Z

I tested with latest version (software.amazon.awssdk:s3:2.23.10, software.amazon.awssdk.crt:aws-crt:0.29.7) and got same results...

zoewangg · 2024-02-06T00:23:29Z

Thank you for the detailed analysis. It makes sense; we need to cancel the upstream subscription when the downstream subscription is cancelled.

kxk · 2024-02-26T20:56:52Z

Seeing the exact same behavior. Following the issue. Thanks!

github-actions · 2024-02-27T21:34:13Z

This issue is now closed. Comments on closed issues are hard for our team to see.
If you need more assistance, please open a new issue that references this one.

chaykin added bug This issue is a bug. needs-triage This issue or PR still needs to be triaged. labels Dec 22, 2023

chaykin pushed a commit to chaykin/aws-sdk-java-v2 that referenced this issue Jan 5, 2024

aws#4801 Cancelling origin body to prevent stuck calling thread

8c0204e

chaykin pushed a commit to chaykin/aws-sdk-java-v2 that referenced this issue Jan 5, 2024

aws#4801 Cancelling origin body to prevent stuck calling thread

a85a651

debora-ito added response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 10 days. and removed needs-triage This issue or PR still needs to be triaged. labels Jan 24, 2024

debora-ito self-assigned this Jan 24, 2024

debora-ito added the p2 This is a standard priority issue label Jan 24, 2024

github-actions bot removed the response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 10 days. label Jan 25, 2024

zoewangg mentioned this issue Feb 27, 2024

Fixed an issue in S3 multipart client where `BlockingInputStreamAsync… #4970

Merged

12 tasks

zoewangg closed this as completed in #4970 Feb 27, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

S3AsyncClient: stuck thread if upload failed #4801

S3AsyncClient: stuck thread if upload failed #4801

chaykin commented Dec 22, 2023 •

edited

Loading

chaykin commented Dec 22, 2023 •

edited

Loading

chaykin commented Jan 5, 2024 •

edited

Loading

debora-ito commented Jan 24, 2024

chaykin commented Jan 25, 2024

zoewangg commented Feb 6, 2024

kxk commented Feb 26, 2024

github-actions bot commented Feb 27, 2024

S3AsyncClient: stuck thread if upload failed #4801

S3AsyncClient: stuck thread if upload failed #4801

Comments

chaykin commented Dec 22, 2023 • edited Loading

Describe the bug

Expected Behavior

Current Behavior

Reproduction Steps

Possible Solution

Additional Information/Context

AWS Java SDK version used

JDK version used

Operating System and version

chaykin commented Dec 22, 2023 • edited Loading

chaykin commented Jan 5, 2024 • edited Loading

debora-ito commented Jan 24, 2024

chaykin commented Jan 25, 2024

zoewangg commented Feb 6, 2024

kxk commented Feb 26, 2024

github-actions bot commented Feb 27, 2024

chaykin commented Dec 22, 2023 •

edited

Loading

chaykin commented Dec 22, 2023 •

edited

Loading

chaykin commented Jan 5, 2024 •

edited

Loading