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.

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

Rapid concurrent S3 uploads sometimes produce a java.io.IOException: Server failed to send complete response #452

Closed
ochrons opened this issue Apr 4, 2018 · 14 comments
Labels
bug This issue is a bug. Netty NIO Client pending-release This issue will be fixed by an approved PR that hasn't been released yet.

Comments

@ochrons
Copy link

ochrons commented Apr 4, 2018

Expected Behavior

Uploading thousands of files concurrently to S3

Current Behavior

Previously we suffered from #202 but that seems to have been fixed in SDK preview-9. The new problem is similar, except it happens quite rarely, once per tens of thousands of uploads. We use multipart uploading for all uploads.

In one test case I was uploading batches of 1000 files each, running 32 uploads concurrently. The error happened on the first file of the first batch and also on the fifth file on the first batch. All other batches uploaded without errors.

Internally our service extracts individual files from the batches and uploads them to S3 using the new async API, so the total number of concurrent requests to S3 is probably quite high.

The error originates from

public void channelInactive(ChannelHandlerContext handlerCtx) throws Exception {
RequestContext requestCtx = handlerCtx.channel().attr(REQUEST_CONTEXT_KEY).get();
boolean responseCompleted = handlerCtx.channel().attr(RESPONSE_COMPLETE_KEY).get();
if (!responseCompleted) {
runAndLogError("SdkHttpResponseHandler threw an exception when calling exceptionOccurred",
() -> requestCtx.handler().exceptionOccurred(new IOException("Server failed to send complete response")));
runAndLogError("Could not release channel",
() -> requestCtx.channelPool().release(handlerCtx.channel()));
}
}

Steps to Reproduce (for bugs)

Upload lots of files to S3 concurrently.

Your Environment

AWS SDK preview-9
JDK8
AWS Linux
i3.xlarge EC2 instance

@dagnir dagnir added investigating This issue is being investigated and/or work is in progress to resolve the issue. Netty NIO Client labels Jun 4, 2018
@dagnir
Copy link
Contributor

dagnir commented Jun 7, 2018

This was a quirk we noticed when we originally debugged #202. Basically what would happen is that when connecting to S3 over TLS, on very rare occasions, S3 will suddenly close the connection after the request is sent rather than sending a response. Curiously, it does not seem to happen when connected over unencrypted HTTP.

There are a couple issues that look quite similar that have been reported to the PHP SDK: aws/aws-sdk-php#983

@dagnir
Copy link
Contributor

dagnir commented Jun 8, 2018

I think it makes sense to treat this as a retryable exception.

@dagnir dagnir added bug This issue is a bug. and removed investigating This issue is being investigated and/or work is in progress to resolve the issue. labels Jun 8, 2018
@bollmann
Copy link

bollmann commented Aug 8, 2018

We're also getting the same exception every once in a while even with AWS SDK "2.0.0-preview-11". We're using the following asynchronous s3 client in scala:

val amazonS3 = S3AsyncClient.builder()
      .httpClient(NettyNioAsyncHttpClient)
      .credentialsProvider(StaticCredentialsProvider.create(
        AwsBasicCredentials.create(settings.s3AccessId, settings.s3SecretAccessKey)))
      .region(Region.of(settings.s3Region))
      .build()

And making the following requests:

    val request = GetObjectTaggingRequest.builder()
      .bucket(bucketName)
      .key(keyName)
      .build()

    val futureResponse = amazonS3.getObjectTagging(request)

And every once in a while, futureResponse fails with an java.io.IOException: "Server failed to send complete response" error.

If anyone knows why this may be, I would highly appreciate it! :-)

Note: we're using scala, version "2.11.11" (on top of the openjdk version "1.8.0_171"). And we're running on ubuntu 16.04.

@bollmann
Copy link

Debugging (my) above issue further, it seems to have to do with SSL and the fact that channels are reused. To give you a little bit of context: using the above amazonS3 client we we make the above request every 60 seconds. And it seems that making this HTTPS request for the very first time using a fresh channel (i.e., one that has just been registered) works fine. However, when again making the this request 60 seconds later, the already established channel is tried to be reused and at that point the SSL connection is closed prematurely (?). This pattern generalizes and I always see a freshly created channel to be able to carry its first HTTP request but failing to also transport the subsequent HTTP request 60 seconds later.

Here are the exact logs:

2018-08-16 07:04:25,906 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f] CHANNEL_REGISTERED
2018-08-16 07:04:25,907 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f] CONNECT

<some-bucket>.s3.amazonaws.com/54.231.73.19:443

2018-08-16 07:04:25,909 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] CHANNEL_ACTIVE
2018-08-16 07:04:25,910 DEBUG [aws-java-sdk-NettyEventLoop-0-1] RunnableRequest {software.amazon.awssdk.http.nio.netty.internal.RunnableRequest makeRequest in RunnableRequest.java:97} - Writing request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)

GET https://<some-bucket>.s3.amazonaws.com/some/uri?tagging HTTP/1.1
Authorization: <some authorization value>
Host: <some-bucket>.s3.amazonaws.com
User-Agent: aws-sdk-java/2.0.0-preview-11 Linux/4.4.0-1063-aws OpenJDK_64-Bit_Server_VM/25.181-b13 Java/1.8.0_181 scala/2.11.11
x-amz-content-sha256: UNSIGNED-PAYLOAD
X-Amz-Date: 20180816T070425Z

2018-08-16 07:04:25,910 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) WRITE

software.amazon.awssdk.http.nio.netty.internal.RunnableRequest$StreamedRequest(DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)

GET https://<some-bucket>.s3.amazonaws.com/some/uri?tagging HTTP/1.1
Authorization: <some authorization value>
Host: <some-bucket>.s3.amazonaws.com
User-Agent: aws-sdk-java/2.0.0-preview-11 Linux/4.4.0-1063-aws OpenJDK_64-Bit_Server_VM/25.181-b13 Java/1.8.0_181 scala/2.11.11
x-amz-content-sha256: UNSIGNED-PAYLOAD
X-Amz-Date: 20180816T070425Z)

2018-08-16 07:04:25,910 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) FLUSH
2018-08-16 07:04:25,910 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) FLUSH
2018-08-16 07:04:25,910 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) WRITE 0 bytes

DefaultHttpContent(data: PooledUnsafeDirectByteBuf(ridx: 0, widx: 0, cap: 0), decoderResult: success)

2018-08-16 07:04:25,911 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) FLUSH
2018-08-16 07:04:25,911 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (inbound) READ_COMPLETE
2018-08-16 07:04:25,911 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (inbound) READ_COMPLETE
2018-08-16 07:04:25,913 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (inbound) READ_COMPLETE
2018-08-16 07:04:25,915 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (inbound) READ_COMPLETE
2018-08-16 07:04:25,917 DEBUG [aws-java-sdk-NettyEventLoop-0-0] SslHandler {io.netty.util.internal.logging.Slf4JLogger debug in Slf4JLogger.java:81} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2018-08-16 07:04:25,917 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] USER_EVENT_TRIGGERED

SslHandshakeCompletionEvent(SUCCESS)

2018-08-16 07:04:25,917 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) WRITE 0 bytes

EmptyLastHttpContent

2018-08-16 07:04:25,917 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) FLUSH
2018-08-16 07:04:25,918 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (inbound) READ_COMPLETE
2018-08-16 07:04:25,946 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (inbound) RECEIVED

DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)

HTTP/1.1 200 OK
Date: Thu, 16 Aug 2018 07:04:26 GMT
Transfer-Encoding: chunked
Server: AmazonS3

2018-08-16 07:04:25,950 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (inbound) RECEIVED 115 bytes

DefaultHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 115, cap: 115/115, unwrapped: PooledUnsafeDirectByteBuf(ridx: 349, widx: 349, cap: 407)), decoderResult: success)

         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 3c 3f 78 6d 6c 20 76 65 72 73 69 6f 6e 3d 22 31 |<?xml version="1|
|00000010| 2e 30 22 20 65 6e 63 6f 64 69 6e 67 3d 22 55 54 |.0" encoding="UT|
|00000020| 46 2d 38 22 3f 3e 0a 3c 54 61 67 67 69 6e 67 20 |F-8"?>.<Tagging |
|00000030| 78 6d 6c 6e 73 3d 22 68 74 74 70 3a 2f 2f 73 33 |xmlns="http://s3|
|00000040| 2e 61 6d 61 7a 6f 6e 61 77 73 2e 63 6f 6d 2f 64 |.amazonaws.com/d|
|00000050| 6f 63 2f 32 30 30 36 2d 30 33 2d 30 31 2f 22 3e |oc/2006-03-01/">|
|00000060| 3c 54 61 67 53 65 74 2f 3e 3c 2f 54 61 67 67 69 |<TagSet/></Taggi|
|00000070| 6e 67 3e                                        |ng>             |
+--------+-------------------------------------------------+----------------+

2018-08-16 07:04:25,950 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (inbound) READ_COMPLETE
2018-08-16 07:04:25,950 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (inbound) RECEIVED 0 bytes

EmptyLastHttpContent

############################################################################################
############################################################################################
#                                                                                          #
# At this point, futureResponse completes successfully! Afterwards, other HTTPS requests   #
# (unrelated to channel 0x8398eb5f) happen here for one minute.                            #
#                                                                                          #
############################################################################################
############################################################################################

c018-08-16 07:05:25,906 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) WRITE

software.amazon.awssdk.http.nio.netty.internal.RunnableRequest$StreamedRequest(DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)

GET https://<some-bucket>.s3.amazonaws.com/some/uri?tagging HTTP/1.1
Authorization: <some authorization value>
Host: <some-bucket>.s3.amazonaws.com
User-Agent: aws-sdk-java/2.0.0-preview-11 Linux/4.4.0-1063-aws OpenJDK_64-Bit_Server_VM/25.181-b13 Java/1.8.0_181 scala/2.11.11
x-amz-content-sha256: UNSIGNED-PAYLOAD
X-Amz-Date: 20180816T070525Z)

2018-08-16 07:05:25,906 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) FLUSH
2018-08-16 07:05:25,906 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) FLUSH
2018-08-16 07:05:25,906 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) WRITE 0 bytes

DefaultHttpContent(data: PooledUnsafeDirectByteBuf(ridx: 0, widx: 0, cap: 0), decoderResult: success)

2018-08-16 07:05:25,906 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) FLUSH
2018-08-16 07:05:25,907 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) WRITE 0 bytes

EmptyLastHttpContent

2018-08-16 07:05:25,907 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (outbound) FLUSH
2018-08-16 07:05:25,907 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] USER_EVENT_TRIGGERED

SslCloseCompletionEvent(SUCCESS)

2018-08-16 07:05:25,907 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (inbound) READ_COMPLETE
2018-08-16 07:05:25,907 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 - R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] (inbound) READ_COMPLETE
2018-08-16 07:05:25,908 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 ! R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] CHANNEL_INACTIVE
2018-08-16 07:05:25,909 DEBUG [aws-java-sdk-NettyEventLoop-0-0] ChannelPipelineInitializer {software.amazon.awssdk.utils.Logger debug in Logger.java:80} - [id: 0x8398eb5f, L:/172.18.0.2:55278 ! R:<some-bucket>.s3.amazonaws.com/54.231.73.19:443] CHANNEL_UNREGISTERED

############################################################################################
############################################################################################
#                                                                                          #
# At this point futureResponse completes exceptionally! (See the below exception!)         #
#                                                                                          #
############################################################################################
############################################################################################


java.util.concurrent.CompletionException: software.amazon.awssdk.core.exception.SdkClientException

	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292)
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308)
	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:593)
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryExecutor.handle(AsyncRetryableStage.java:136)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryExecutor.lambda$execute$0(AsyncRetryableStage.java:117)
	at java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:822)
	at java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:797)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage$Completable.lambda$completeExceptionally$1(MakeAsyncHttpRequestStage.java:223)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
  
Caused by: software.amazon.awssdk.core.exception.SdkClientException: null
	at software.amazon.awssdk.core.exception.SdkClientException$BuilderImpl.build(SdkClientException.java:93)
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryExecutor.handle(AsyncRetryableStage.java:131)
	... 9 common frames omitted

Caused by: java.io.IOException: Server failed to send complete response
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.lambda$channelInactive$2(ResponseHandler.java:131)
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.runAndLogError(ResponseHandler.java:156)
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.channelInactive(ResponseHandler.java:130)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
	at software.amazon.awssdk.http.nio.netty.internal.utils.LoggingHandler.channelInactive(LoggingHandler.java:61)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:420)
	at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:377)
	at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:342)
	at io.netty.handler.codec.http.HttpClientCodec$Decoder.channelInactive(HttpClientCodec.java:282)
	at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:223)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
	at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:377)
	at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:342)
	at io.netty.handler.ssl.SslHandler.channelInactive(SslHandler.java:1028)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
	at io.netty.handler.timeout.IdleStateHandler.channelInactive(IdleStateHandler.java:277)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1429)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
	at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:947)
	at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:822)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:464)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
	... 1 common frames omitted

@bollmann
Copy link

To reproduce the error, I created a minimal code snippet:

import java.util.function.BiConsumer

import com.typesafe.scalalogging.LazyLogging
import software.amazon.awssdk.auth.credentials.{AwsBasicCredentials, StaticCredentialsProvider}
import software.amazon.awssdk.http.nio.netty.NettyNioAsyncHttpClient
import software.amazon.awssdk.regions.Region
import software.amazon.awssdk.services.s3.S3AsyncClient
import software.amazon.awssdk.services.s3.model.{GetObjectTaggingRequest, GetObjectTaggingResponse}

object AwsBug extends LazyLogging {

  def main(args: Array[String]): Unit = {

    val s3AccessId = "your access id"                                    // set me!
    val s3SecretAccessKey = "your secret access key"                     // set me!

    val bucketName = "specify an existing bucket here!"                  // set me!
    val keyName = "specify an existing key inside your bucket here!"     // set me!

    val amazonS3 = S3AsyncClient.builder()
      .httpClient(NettyNioAsyncHttpClient.builder().build())
      .credentialsProvider(StaticCredentialsProvider.create(
        AwsBasicCredentials.create(s3AccessId, s3SecretAccessKey)))
      .region(Region.of("us-east-1"))
      .build()

    val request = GetObjectTaggingRequest.builder()
      .bucket(bucketName)
      .key(keyName)
      .build()

    val responseHandler = new BiConsumer[GetObjectTaggingResponse, Throwable] {
      override def accept(resp: GetObjectTaggingResponse, ex: Throwable): Unit = {
        if (ex == null)
          logger.info("responseHandler: SUCCESS")
        else
          logger.error("responseHandler: FAILURE!", ex)
      }
    }

    while (true) {
      val futureResponse = amazonS3.getObjectTagging(request)
      futureResponse whenComplete responseHandler

      Thread.sleep(60 * 1000L)
    }
  }
}

Leaving that code running for at least some hours causes the above exception with very high likelyhood to occur on my machine. It should equally well be reproducible in Java.

@anti-framework
Copy link

anti-framework commented Nov 15, 2018

The same behavior while using SQS service
SendMessageRequest smr = SendMessageRequest.builder() .queueUrl(queueUrl + "/" + queueName) .messageBody(json) .messageAttributes(Collections.singletonMap(ATTRIBUTE_SERIAL, MessageAttributeValue.builder() .stringValue(serial) .dataType("String") .build())) .build();
`
sqsAsyncClient.sendMessage(smr).whenComplete((response, ex) -> {

				if (ex != null) {
					ex.printStackTrace();
										}
			});` 

when the pressure gets about 400 messages per second, some of requests (not many) cause the same

Server failed to send complete response exception

I am using 2.0.0-preview-13 version

@zoewangg
Copy link
Contributor

Thank all of you for the thorough reports. The issue has been fixed in #834.

@zoewangg
Copy link
Contributor

The fix has been released as part of 2.1.0. Closing the issue.

@ShibaBandit
Copy link

I still see this issue in 2.3.9... did this fix it for you @ochrons ?

@spfink
Copy link
Contributor

spfink commented Jan 31, 2019

@ShibaBandit, #1041, which will go out on Monday will also help to significantly reduce the chances of this occurring.

aws-sdk-java-automation added a commit that referenced this issue Mar 19, 2019
…24d8d0b4

Pull request: release <- staging/97244113-58b1-42aa-b196-2bd624d8d0b4
@justnance justnance added pending-release This issue will be fixed by an approved PR that hasn't been released yet. and removed awaiting-release labels Apr 19, 2019
@austince
Copy link

austince commented Nov 1, 2019

I'm still seeing this in 2.7.33 - is anyone else? We are managing our own Thread Pool, could this be contributing to the issue? Using JDK 8. Trying to see if #1122 (comment) will fix it

@ghost
Copy link

ghost commented Nov 14, 2019

I am using SnsAsyncClient with NettyNioAsyncHttpClient as the http client and I can see similar errors. I am using 2.8.7

@alejandrod
Copy link

Same issue here with SnsAsyncClient, NettyNioAsyncHttpClient and 2.10.18
If this is because of bursts, maybe an option could be added to backoff a bit or similar.

@cgallom
Copy link

cgallom commented May 2, 2024

see this issue in 2.3.9... did this fix it for you @ochrons ?

@zoewangg This is not fixed as I Noticed. I Have read same response from your side and closing unresolved issues on other posts. I think You shouldn't proceed to close posts if you are not sure if releases fix it. It is still happening in 2024 I have same issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug This issue is a bug. Netty NIO Client pending-release This issue will be fixed by an approved PR that hasn't been released yet.
Projects
None yet
Development

No branches or pull requests