Aws-sdk-java-v2: Rapid concurrent S3 uploads sometimes produce a java.io.IOException: Server failed to send complete response

Created on 5 Apr 2018  路  13Comments  路  Source: aws/aws-sdk-java-v2

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 https://github.com/aws/aws-sdk-java-v2/blob/1c8ae1457caf9e45a3c17f672136708fa16e2489/http-clients/netty-nio-client/src/main/java/software/amazon/awssdk/http/nio/netty/internal/ResponseHandler.java#L124-L133

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

Netty NIO Client bug pending-release
Source
picture ochrons
👍8

All 13 comments

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: https://github.com/aws/aws-sdk-php/issues/983

dagnir picture dagnir on 8 Jun 2018

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

dagnir picture dagnir on 8 Jun 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 picture bollmann on 8 Aug 2018

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 picture bollmann on 16 Aug 2018

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.

bollmann picture bollmann on 24 Aug 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

anti-framework picture anti-framework on 15 Nov 2018

Thank all of you for the thorough reports. The issue has been fixed in https://github.com/aws/aws-sdk-java-v2/pull/834.

zoewangg picture zoewangg on 19 Nov 2018

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

zoewangg picture zoewangg on 20 Nov 2018
👍1

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

ShibaBandit picture ShibaBandit on 31 Jan 2019

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

spfink picture spfink on 31 Jan 2019
👍1

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 https://github.com/aws/aws-sdk-java-v2/issues/1122#issuecomment-518327601 will fix it

austince picture austince on 1 Nov 2019
👍1

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

wangdanny picture wangdanny on 14 Nov 2019

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.

alejandrod picture alejandrod on 21 Nov 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

aeons picture aeons  路  4Comments
tigertoes picture tigertoes  路  6Comments
david-katz picture david-katz  路  3Comments
deepankerk picture deepankerk  路  5Comments
SamBumgardner picture SamBumgardner  路  4Comments