Skip to content

Slow first call while using multiple SqsAsyncClient because of underlining io.netty.handler.timeout.ReadTimeoutException #2146

New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom
Closed
amrynsky opened this issue Nov 13, 2020 · 4 comments
Closed

Slow first call while using multiple SqsAsyncClient because of underlining io.netty.handler.timeout.ReadTimeoutException #2146

amrynsky opened this issue Nov 13, 2020 · 4 comments
Labels
bug This issue is a bug. needs-triage This issue or PR still needs to be triaged.

Comments

@amrynsky
Copy link

Slow first call while using multiple SqsAsyncClient because of underlining io.netty.handler.timeout.ReadTimeoutException

Details

We are using SqsAsyncClient and observed strange behavior while using multiple clients. In the following code, the first call to client2 is always slow taking ~30sec

SqsAsyncClient client1 = createSqsClient();
createQueue(client1, "test");
createQueue(client1, "test");

SqsAsyncClient client2 = createSqsClient();
createQueue(client2, "test");
createQueue(client2, "test");

Here is a log from our test:

08:38:59.302  [Test worker] INFO [c.p.p.s.a.s.AwsSqsAsyncClientTest] - client1 finished in 404ms
08:38:59.336  [Test worker] INFO [c.p.p.s.a.s.AwsSqsAsyncClientTest] - client1 finished in 34ms
08:39:29.474  [Test worker] INFO [c.p.p.s.a.s.AwsSqsAsyncClientTest] - client2 finished in **30137ms**
08:39:29.499  [Test worker] INFO [c.p.p.s.a.s.AwsSqsAsyncClientTest] - client2 finished in 24ms

in DEBUG logs we see the first HTTP call of the new client always results in io.netty.handler.timeout.ReadTimeoutException . It works after retry and all subsequent calls are also good.

09:03:42.911  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] DEBUG [i.n.h.l.LoggingHandler] - [id: 0x32315beb, L:/127.0.0.1:60690 - R:/127.0.0.1:33447] FLUSH
09:03:42.912  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] DEBUG [i.n.h.l.LoggingHandler] - [id: 0x32315beb, L:/127.0.0.1:60690 - R:/127.0.0.1:33447] WRITE, EmptyLastHttpContent, 0B
09:03:42.912  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] DEBUG [i.n.h.l.LoggingHandler] - [id: 0x32315beb, L:/127.0.0.1:60690 - R:/127.0.0.1:33447] FLUSH
09:03:47.882  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-2] DEBUG [s.a.a.h.n.n.i.IdleConnectionReaperHandler] - Closing unused connection (f8ed65be) because it has been idle for longer than 5000 milliseconds.
09:03:47.885  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-2] DEBUG [i.n.h.l.LoggingHandler] - [id: 0xf8ed65be, L:/127.0.0.1:60688 ! R:/127.0.0.1:33447] INACTIVE
09:03:47.886  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-2] DEBUG [i.n.h.l.LoggingHandler] - [id: 0xf8ed65be, L:/127.0.0.1:60688 ! R:/127.0.0.1:33447] UNREGISTERED
09:04:12.915  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] DEBUG [i.n.h.l.LoggingHandler] - [id: 0x32315beb, L:/127.0.0.1:60690 - R:/127.0.0.1:33447] EXCEPTION: io.netty.handler.timeout.ReadTimeoutException
io.netty.handler.timeout.ReadTimeoutException: null
09:04:12.915  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] DEBUG [s.a.a.h.n.n.i.ResponseHandler] - Exception processing request: DefaultSdkHttpFullRequest(httpMethod=POST, protocol=http, host=127.0.0.1, port=33447, encodedPath=, headers=[amz-sdk-invocation-id, amz-sdk-retry, Authorization, Content-Length, Content-Type, Host, User-Agent, X-Amz-Date], queryParameters=[])
io.netty.handler.timeout.ReadTimeoutException: null
09:04:12.923  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] DEBUG [s.a.a.request] - Retryable error detected. Will retry in 55ms. Request attempt number 2
software.amazon.awssdk.core.exception.SdkClientException: Unable to execute HTTP request: Read timed out
	at software.amazon.awssdk.core.exception.SdkClientException$BuilderImpl.build(SdkClientException.java:98) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.core.exception.SdkClientException.create(SdkClientException.java:43) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.RetryableStageHelper.setLastException(RetryableStageHelper.java:205) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.RetryableStageHelper.setLastException(RetryableStageHelper.java:201) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.maybeRetryExecute(AsyncRetryableStage.java:143) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.lambda$attemptExecute$1(AsyncRetryableStage.java:125) ~[sdk-core-2.15.26.jar:?]
	at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at software.amazon.awssdk.utils.CompletableFutureUtils.lambda$forwardExceptionTo$0(CompletableFutureUtils.java:74) ~[utils-2.15.26.jar:?]
	at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage.lambda$null$0(MakeAsyncHttpRequestStage.java:104) ~[sdk-core-2.15.26.jar:?]
	at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage$WrappedErrorForwardingResponseHandler.onError(MakeAsyncHttpRequestStage.java:158) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.lambda$exceptionCaught$0(ResponseHandler.java:146) ~[netty-nio-client-2.15.26.jar:?]
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.runAndLogError(ResponseHandler.java:180) [netty-nio-client-2.15.26.jar:?]
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.exceptionCaught(ResponseHandler.java:146) [netty-nio-client-2.15.26.jar:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.handler.logging.LoggingHandler.exceptionCaught(LoggingHandler.java:205) [netty-handler-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at software.amazon.awssdk.http.nio.netty.internal.UnusedChannelExceptionHandler.exceptionCaught(UnusedChannelExceptionHandler.java:52) [netty-nio-client-2.15.26.jar:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at software.amazon.awssdk.http.nio.netty.internal.FutureCancelHandler.exceptionCaught(FutureCancelHandler.java:47) [netty-nio-client-2.15.26.jar:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireExceptionCaught(CombinedChannelDuplexHandler.java:424) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.ChannelHandlerAdapter.exceptionCaught(ChannelHandlerAdapter.java:92) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.CombinedChannelDuplexHandler$1.fireExceptionCaught(CombinedChannelDuplexHandler.java:145) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:143) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.CombinedChannelDuplexHandler.exceptionCaught(CombinedChannelDuplexHandler.java:231) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.handler.timeout.ReadTimeoutHandler.readTimedOut(ReadTimeoutHandler.java:98) [netty-handler-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.handler.timeout.ReadTimeoutHandler.channelIdle(ReadTimeoutHandler.java:90) [netty-handler-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.handler.timeout.IdleStateHandler$ReaderIdleTimeoutTask.run(IdleStateHandler.java:504) [netty-handler-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.handler.timeout.IdleStateHandler$AbstractIdleTask.run(IdleStateHandler.java:476) [netty-handler-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: java.io.IOException: Read timed out
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.wrapException(ResponseHandler.java:385) ~[netty-nio-client-2.15.26.jar:?]
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.exceptionCaught(ResponseHandler.java:144) ~[netty-nio-client-2.15.26.jar:?]
	... 35 more
Caused by: io.netty.handler.timeout.ReadTimeoutException
09:04:12.929  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] DEBUG [i.n.h.l.LoggingHandler] - [id: 0x32315beb, L:/127.0.0.1:60690 ! R:/127.0.0.1:33447] CLOSE
09:04:12.933  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] DEBUG [i.n.h.l.LoggingHandler] - [id: 0x32315beb, L:/127.0.0.1:60690 ! R:/127.0.0.1:33447] CLOSE
09:04:12.934  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] DEBUG [i.n.h.l.LoggingHandler] - [id: 0x32315beb, L:/127.0.0.1:60690 ! R:/127.0.0.1:33447] INACTIVE
09:04:12.934  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] DEBUG [i.n.h.l.LoggingHandler] - [id: 0x32315beb, L:/127.0.0.1:60690 ! R:/127.0.0.1:33447] UNREGISTERED
09:04:12.982  trace:[] span:[] [sdk-ScheduledExecutor-4-0] DEBUG [s.a.a.request] - Retrying Request: DefaultSdkHttpFullRequest(httpMethod=POST, protocol=http, host=127.0.0.1, port=33447, encodedPath=, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, User-Agent], queryParameters=[])

Steps to Reproduce

Here is a code snippet to reproduce the issue.

        @Test
	void createQueueTest() {
		SqsAsyncClient client1 = createSqsClient();

		record(() -> createQueue(client1, "test"));
		record(() -> createQueue(client1, "test"));

		SqsAsyncClient client2 = createSqsClient();

		record(() -> createQueue(client2, "test"));
		record(() -> createQueue(client2, "test"));
	}

	private void createQueue(SqsAsyncClient client, String name) {
		CreateQueueRequest createQueueRequest = CreateQueueRequest.builder()
				.queueName(name)
				.build();

		client.createQueue(createQueueRequest).join();
	}

	private SqsAsyncClient createSqsClient() {
		return SqsAsyncClient.builder()
				.credentialsProvider(provider)
				.endpointOverride(endpoint)
				.region(Region.US_WEST_2)
				.build();
	}

	private void record(Runnable f) {
		Instant start = Instant.now();
		try {
			f.run();
		} finally {
			log.info("finished in " + Duration.between(start, Instant.now()).toMillis() + "ms");
		}
	}

Possible Solution

Need to look into code to understand the root cause

Context

This is not real use case because in our service we are sharing the same client across different components. But it could be relevant for some use cases in the future - for example, creating a client per region. We came across this while writing unit tests where we create a new client in @BeforeEach.

Environment

  • AWS Java SDK version used: 2.15.26, Netty - 4.1.51.Final
  • JDK version used: OpenJDK Runtime Environment (build 14.0.1+7)
  • Operating System and version: Mac_OS_X/10.15.7
@amrynsky amrynsky added bug This issue is a bug. needs-triage This issue or PR still needs to be triaged. labels Nov 13, 2020
@amrynsky
Copy link
Author

here is more information about the issue but with different results. In our test we are trying to create a new SQS queue with a unique name and sometimes it results in the following error

software.amazon.awssdk.services.sqs.model.SqsException: Concurrent access: Queue already exists: processMessages-dfc50594-17f4-4d21-886b-0745b4ba9e64; see the SQS docs. (Service: Sqs, Status Code: 400, Request ID: 00000000-0000-0000-0000-000000000000, Extended Request ID: null)

There is nothing special in this test - we just wrapped createQueue in reactive Mono

Mono.fromFuture(sqsClient.createQueue(request))

Here is a full log

11:08:31.708  trace:[] span:[] [Test worker] ?[34mDEBUG?[m [s.a.a.c.i.ExecutionInterceptorChain] - Creating an interceptor chain that will apply interceptors in the following order: [software.amazon.awssdk.core.internal.interceptor.HttpChecksumRequiredInterceptor@23f9e716, software.amazon.awssdk.awscore.interceptor.HelpfulUnknownHostExceptionInterceptor@710c35b4, software.amazon.awssdk.services.sqs.internal.MessageMD5ChecksumInterceptor@6693624, software.amazon.awssdk.protocols.query.interceptor.QueryParametersToBodyInterceptor@3aa31a8f]
11:08:31.709  trace:[] span:[] [Test worker] ?[34mDEBUG?[m [s.a.a.c.i.ExecutionInterceptorChain] - Interceptor 'software.amazon.awssdk.protocols.query.interceptor.QueryParametersToBodyInterceptor@3aa31a8f' modified the message with its modifyHttpRequest method.
11:08:31.710  trace:[] span:[] [Test worker] ?[34mDEBUG?[m [s.a.a.request] - Sending Request: DefaultSdkHttpFullRequest(httpMethod=POST, protocol=http, host=127.0.0.1, port=35677, encodedPath=, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, User-Agent], queryParameters=[])
11:08:31.711  trace:[] span:[] [Test worker] ?[34mDEBUG?[m [s.a.a.a.s.Aws4Signer] - AWS4 String to sign: AWS4-HMAC-SHA256
20201120T190831Z
20201120/us-east-1/sqs/aws4_request
9a21693b84aa7053f63f1a3bf51b63c8efe59908df49b89bde9fa6d64e28f09e
11:08:31.714  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62] REGISTERED
11:08:31.714  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62] CONNECT: /127.0.0.1:35677
11:08:31.715  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] ACTIVE
11:08:31.716  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6] REGISTERED
11:08:31.717  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6] CONNECT: /127.0.0.1:35677
11:08:31.718  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 - R:/127.0.0.1:35677] ACTIVE
11:08:31.719  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 - R:/127.0.0.1:35677] WRITE: software.amazon.awssdk.http.nio.netty.internal.NettyRequestExecutor$StreamedRequest(DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST / HTTP/1.1
Host: 127.0.0.1:35677
amz-sdk-invocation-id: 3afaabb9-da87-75ce-2fe0-009212b80b05
amz-sdk-retry: 0/0/
Authorization: AWS4-HMAC-SHA256 Credential=accesskey/20201120/us-east-1/sqs/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-retry;content-length;content-type;host;x-amz-date, Signature=9ba43c117ccb70349b101d56df0ced4431f9e7f5d1fb3e69f0fc591b2eef2bb0
Content-Length: 100
Content-Type: application/x-www-form-urlencoded; charset=utf-8
User-Agent: aws-sdk-java/2.15.26 Linux/4.4.0-122-generic OpenJDK_64-Bit_Server_VM/14.0.2+12-46 Java/14.0.2 vendor/Oracle_Corporation io/async http/NettyNio
X-Amz-Date: 20201120T190831Z)
11:08:31.720  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 - R:/127.0.0.1:35677] FLUSH
11:08:31.721  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 - R:/127.0.0.1:35677] FLUSH
11:08:31.721  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 - R:/127.0.0.1:35677] WRITE: DefaultHttpContent(data: UnpooledHeapByteBuf(ridx: 0, widx: 100, cap: 100/100), decoderResult: success), 100B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 41 63 74 69 6f 6e 3d 43 72 65 61 74 65 51 75 65 |Action=CreateQue|
|00000010| 75 65 26 56 65 72 73 69 6f 6e 3d 32 30 31 32 2d |ue&Version=2012-|
|00000020| 31 31 2d 30 35 26 51 75 65 75 65 4e 61 6d 65 3d |11-05&QueueName=|
|00000030| 70 72 6f 63 65 73 73 4d 65 73 73 61 67 65 73 2d |processMessages-|
|00000040| 64 66 63 35 30 35 39 34 2d 31 37 66 34 2d 34 64 |dfc50594-17f4-4d|
|00000050| 32 31 2d 38 38 36 62 2d 30 37 34 35 62 34 62 61 |21-886b-0745b4ba|
|00000060| 39 65 36 34                                     |9e64            |
+--------+-------------------------------------------------+----------------+
11:08:31.722  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 - R:/127.0.0.1:35677] FLUSH
11:08:31.722  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 - R:/127.0.0.1:35677] WRITE, EmptyLastHttpContent, 0B
11:08:31.722  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 - R:/127.0.0.1:35677] FLUSH
11:08:33.714  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-10] ?[34mDEBUG?[m [s.a.a.h.n.n.i.IdleConnectionReaperHandler] - Closing unused connection (d46a4ae3) because it has been idle for longer than 5000 milliseconds.
11:08:33.716  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-10] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xd46a4ae3, L:/127.0.0.1:57292 ! R:/127.0.0.1:35677] INACTIVE
11:08:33.717  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-10] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xd46a4ae3, L:/127.0.0.1:57292 ! R:/127.0.0.1:35677] UNREGISTERED
11:08:33.739  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-10] ?[34mDEBUG?[m [s.a.a.h.n.n.i.IdleConnectionReaperHandler] - Closing unused connection (4f4fc761) because it has been idle for longer than 5000 milliseconds.
11:08:33.739  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-10] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x4f4fc761, L:/127.0.0.1:57304 ! R:/127.0.0.1:35677] INACTIVE
11:08:33.740  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-10] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x4f4fc761, L:/127.0.0.1:57304 ! R:/127.0.0.1:35677] UNREGISTERED
11:08:33.751  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-14] ?[34mDEBUG?[m [s.a.a.h.n.n.i.IdleConnectionReaperHandler] - Closing unused connection (595e9262) because it has been idle for longer than 5000 milliseconds.
11:08:33.752  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-14] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x595e9262, L:/127.0.0.1:57296 ! R:/127.0.0.1:35677] INACTIVE
11:08:33.752  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-14] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x595e9262, L:/127.0.0.1:57296 ! R:/127.0.0.1:35677] UNREGISTERED
11:08:33.758  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-0] ?[34mDEBUG?[m [s.a.a.h.n.n.i.IdleConnectionReaperHandler] - Closing unused connection (75e8b2ca) because it has been idle for longer than 5000 milliseconds.
11:08:33.758  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-0] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x75e8b2ca, L:/127.0.0.1:57284 ! R:/127.0.0.1:35677] INACTIVE
11:08:33.758  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-0] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x75e8b2ca, L:/127.0.0.1:57284 ! R:/127.0.0.1:35677] UNREGISTERED
11:08:33.772  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-9] ?[34mDEBUG?[m [s.a.a.h.n.n.i.IdleConnectionReaperHandler] - Closing unused connection (da064e67) because it has been idle for longer than 5000 milliseconds.
11:08:33.773  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-9] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xda064e67, L:/127.0.0.1:57300 ! R:/127.0.0.1:35677] INACTIVE
11:08:33.773  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-9] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xda064e67, L:/127.0.0.1:57300 ! R:/127.0.0.1:35677] UNREGISTERED
11:08:33.777  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-14] ?[34mDEBUG?[m [s.a.a.h.n.n.i.IdleConnectionReaperHandler] - Closing unused connection (d9b3a6f1) because it has been idle for longer than 5000 milliseconds.
11:08:33.778  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-14] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xd9b3a6f1, L:/127.0.0.1:57316 ! R:/127.0.0.1:35677] INACTIVE
11:08:33.778  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-14] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xd9b3a6f1, L:/127.0.0.1:57316 ! R:/127.0.0.1:35677] UNREGISTERED
11:08:33.785  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-0] ?[34mDEBUG?[m [s.a.a.h.n.n.i.IdleConnectionReaperHandler] - Closing unused connection (5ec49720) because it has been idle for longer than 5000 milliseconds.
11:08:33.786  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-0] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x5ec49720, L:/127.0.0.1:57320 ! R:/127.0.0.1:35677] INACTIVE
11:08:33.786  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-0] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x5ec49720, L:/127.0.0.1:57320 ! R:/127.0.0.1:35677] UNREGISTERED
11:08:33.788  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-0] ?[34mDEBUG?[m [s.a.a.h.n.n.i.IdleConnectionReaperHandler] - Closing unused connection (77d48da4) because it has been idle for longer than 5000 milliseconds.
11:08:33.789  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-9] ?[34mDEBUG?[m [s.a.a.h.n.n.i.IdleConnectionReaperHandler] - Closing unused connection (8e6790c6) because it has been idle for longer than 5000 milliseconds.
11:08:33.789  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-0] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x77d48da4, L:/127.0.0.1:57326 ! R:/127.0.0.1:35677] INACTIVE
11:08:33.789  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-0] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x77d48da4, L:/127.0.0.1:57326 ! R:/127.0.0.1:35677] UNREGISTERED
11:08:33.789  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-9] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x8e6790c6, L:/127.0.0.1:57308 ! R:/127.0.0.1:35677] INACTIVE
11:08:33.789  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-9] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x8e6790c6, L:/127.0.0.1:57308 ! R:/127.0.0.1:35677] UNREGISTERED
11:08:34.101  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-2] ?[34mDEBUG?[m [s.a.a.h.n.n.i.IdleConnectionReaperHandler] - Closing unused connection (4b8e902c) because it has been idle for longer than 5000 milliseconds.
11:08:34.102  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-2] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x4b8e902c, L:/127.0.0.1:57268 ! R:/127.0.0.1:35677] INACTIVE
11:08:34.102  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-2] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x4b8e902c, L:/127.0.0.1:57268 ! R:/127.0.0.1:35677] UNREGISTERED
11:09:01.728  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 - R:/127.0.0.1:35677] EXCEPTION: io.netty.handler.timeout.ReadTimeoutException
io.netty.handler.timeout.ReadTimeoutException: null
11:09:01.729  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [s.a.a.h.n.n.i.ResponseHandler] - Exception processing request: DefaultSdkHttpFullRequest(httpMethod=POST, protocol=http, host=127.0.0.1, port=35677, encodedPath=, headers=[amz-sdk-invocation-id, amz-sdk-retry, Authorization, Content-Length, Content-Type, Host, User-Agent, X-Amz-Date], queryParameters=[])
io.netty.handler.timeout.ReadTimeoutException: null
11:09:01.740  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [s.a.a.request] - Retryable error detected. Will retry in 13ms. Request attempt number 2
software.amazon.awssdk.core.exception.SdkClientException: Unable to execute HTTP request: Read timed out
	at software.amazon.awssdk.core.exception.SdkClientException$BuilderImpl.build(SdkClientException.java:98) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.core.exception.SdkClientException.create(SdkClientException.java:43) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.RetryableStageHelper.setLastException(RetryableStageHelper.java:205) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.RetryableStageHelper.setLastException(RetryableStageHelper.java:201) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.maybeRetryExecute(AsyncRetryableStage.java:143) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.lambda$attemptExecute$1(AsyncRetryableStage.java:125) ~[sdk-core-2.15.26.jar:?]
	at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at software.amazon.awssdk.utils.CompletableFutureUtils.lambda$forwardExceptionTo$0(CompletableFutureUtils.java:74) ~[utils-2.15.26.jar:?]
	at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage.lambda$null$0(MakeAsyncHttpRequestStage.java:104) ~[sdk-core-2.15.26.jar:?]
	at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage$WrappedErrorForwardingResponseHandler.onError(MakeAsyncHttpRequestStage.java:158) ~[sdk-core-2.15.26.jar:?]
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.lambda$exceptionCaught$0(ResponseHandler.java:146) ~[netty-nio-client-2.15.26.jar:?]
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.runAndLogError(ResponseHandler.java:180) [netty-nio-client-2.15.26.jar:?]
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.exceptionCaught(ResponseHandler.java:146) [netty-nio-client-2.15.26.jar:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.handler.logging.LoggingHandler.exceptionCaught(LoggingHandler.java:205) [netty-handler-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at software.amazon.awssdk.http.nio.netty.internal.UnusedChannelExceptionHandler.exceptionCaught(UnusedChannelExceptionHandler.java:52) [netty-nio-client-2.15.26.jar:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at software.amazon.awssdk.http.nio.netty.internal.FutureCancelHandler.exceptionCaught(FutureCancelHandler.java:47) [netty-nio-client-2.15.26.jar:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireExceptionCaught(CombinedChannelDuplexHandler.java:424) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.ChannelHandlerAdapter.exceptionCaught(ChannelHandlerAdapter.java:92) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.CombinedChannelDuplexHandler$1.fireExceptionCaught(CombinedChannelDuplexHandler.java:145) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:143) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.CombinedChannelDuplexHandler.exceptionCaught(CombinedChannelDuplexHandler.java:231) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.handler.timeout.ReadTimeoutHandler.readTimedOut(ReadTimeoutHandler.java:98) [netty-handler-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.handler.timeout.ReadTimeoutHandler.channelIdle(ReadTimeoutHandler.java:90) [netty-handler-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.handler.timeout.IdleStateHandler$ReaderIdleTimeoutTask.run(IdleStateHandler.java:504) [netty-handler-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.handler.timeout.IdleStateHandler$AbstractIdleTask.run(IdleStateHandler.java:476) [netty-handler-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) [netty-transport-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.51.Final.jar:4.1.51.Final]
	at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: java.io.IOException: Read timed out
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.wrapException(ResponseHandler.java:385) ~[netty-nio-client-2.15.26.jar:?]
	at software.amazon.awssdk.http.nio.netty.internal.ResponseHandler.exceptionCaught(ResponseHandler.java:144) ~[netty-nio-client-2.15.26.jar:?]
	... 35 more
Caused by: io.netty.handler.timeout.ReadTimeoutException
11:09:01.745  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 ! R:/127.0.0.1:35677] CLOSE
11:09:01.745  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 ! R:/127.0.0.1:35677] CLOSE
11:09:01.746  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 ! R:/127.0.0.1:35677] INACTIVE
11:09:01.746  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-6] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0x2db5c4a6, L:/127.0.0.1:57482 ! R:/127.0.0.1:35677] UNREGISTERED
11:09:01.757  trace:[] span:[] [sdk-ScheduledExecutor-6-0] ?[34mDEBUG?[m [s.a.a.request] - Retrying Request: DefaultSdkHttpFullRequest(httpMethod=POST, protocol=http, host=127.0.0.1, port=35677, encodedPath=, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, User-Agent], queryParameters=[])
11:09:01.758  trace:[] span:[] [sdk-ScheduledExecutor-6-0] ?[34mDEBUG?[m [s.a.a.a.s.Aws4Signer] - AWS4 String to sign: AWS4-HMAC-SHA256
20201120T190901Z
20201120/us-east-1/sqs/aws4_request
ea9ac9118ab0daddcb8cd93bb968c49b808e80a4ba975e2aa9a5c63faab3a441
11:09:01.760  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] WRITE: software.amazon.awssdk.http.nio.netty.internal.NettyRequestExecutor$StreamedRequest(DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST / HTTP/1.1
Host: 127.0.0.1:35677
amz-sdk-invocation-id: 3afaabb9-da87-75ce-2fe0-009212b80b05
amz-sdk-retry: 1/13/495
Authorization: AWS4-HMAC-SHA256 Credential=accesskey/20201120/us-east-1/sqs/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-retry;content-length;content-type;host;x-amz-date, Signature=3fc35260d16bd153b8aeeb5b46e8569a6c9ea8b6b7a489cc2fcf62ff194d7723
Content-Length: 100
Content-Type: application/x-www-form-urlencoded; charset=utf-8
User-Agent: aws-sdk-java/2.15.26 Linux/4.4.0-122-generic OpenJDK_64-Bit_Server_VM/14.0.2+12-46 Java/14.0.2 vendor/Oracle_Corporation io/async http/NettyNio
X-Amz-Date: 20201120T190901Z)
11:09:01.762  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] FLUSH
11:09:01.762  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] FLUSH
11:09:01.762  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] WRITE: DefaultHttpContent(data: UnpooledHeapByteBuf(ridx: 0, widx: 100, cap: 100/100), decoderResult: success), 100B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 41 63 74 69 6f 6e 3d 43 72 65 61 74 65 51 75 65 |Action=CreateQue|
|00000010| 75 65 26 56 65 72 73 69 6f 6e 3d 32 30 31 32 2d |ue&Version=2012-|
|00000020| 31 31 2d 30 35 26 51 75 65 75 65 4e 61 6d 65 3d |11-05&QueueName=|
|00000030| 70 72 6f 63 65 73 73 4d 65 73 73 61 67 65 73 2d |processMessages-|
|00000040| 64 66 63 35 30 35 39 34 2d 31 37 66 34 2d 34 64 |dfc50594-17f4-4d|
|00000050| 32 31 2d 38 38 36 62 2d 30 37 34 35 62 34 62 61 |21-886b-0745b4ba|
|00000060| 39 65 36 34                                     |9e64            |
+--------+-------------------------------------------------+----------------+
11:09:01.763  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] FLUSH
11:09:01.763  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] WRITE, EmptyLastHttpContent, 0B
11:09:01.763  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] FLUSH
11:09:01.798  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] READ: DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 400 Bad Request
Server: BaseHTTP/0.6 Python/3.8.2
Date: Fri, 20 Nov 2020 19:09:01 GMT
Content-Type: text/plain; charset=UTF-8
Content-Length: 483
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: HEAD,GET,PUT,POST,DELETE,OPTIONS,PATCH
Access-Control-Allow-Headers: authorization,content-type,content-md5,cache-control,x-amz-content-sha256,x-amz-date,x-amz-security-token,x-amz-user-agent,x-amz-target,x-amz-acl,x-amz-version-id,x-localstack-target,x-amz-tagging
Access-Control-Expose-Headers: x-amz-version-id
11:09:01.800  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [s.a.a.request] - Received error response: 400
11:09:01.801  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] READ: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 483, cap: 483/483, unwrapped: PooledUnsafeDirectByteBuf(ridx: 1024, widx: 1024, cap: 1024)), decoderResult: success), 483B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 3c 45 72 72 6f 72 52 65 73 70 6f 6e 73 65 20 78 |<ErrorResponse x|
|00000010| 6d 6c 6e 73 3d 22 68 74 74 70 3a 2f 2f 71 75 65 |mlns="http://que|
|00000020| 75 65 2e 61 6d 61 7a 6f 6e 61 77 73 2e 63 6f 6d |ue.amazonaws.com|
|00000030| 2f 64 6f 63 2f 32 30 31 32 2d 31 31 2d 30 35 2f |/doc/2012-11-05/|
|00000040| 22 3e 0a 20 20 20 20 20 20 3c 45 72 72 6f 72 3e |">.      <Error>|
|00000050| 0a 20 20 20 20 20 20 20 20 3c 54 79 70 65 3e 53 |.        <Type>S|
|00000060| 65 6e 64 65 72 3c 2f 54 79 70 65 3e 0a 20 20 20 |ender</Type>.   |
|00000070| 20 20 20 20 20 3c 43 6f 64 65 3e 43 6f 6e 63 75 |     <Code>Concu|
|00000080| 72 72 65 6e 74 20 61 63 63 65 73 73 3a 20 51 75 |rrent access: Qu|
|00000090| 65 75 65 20 61 6c 72 65 61 64 79 20 65 78 69 73 |eue already exis|
|000000a0| 74 73 3a 20 70 72 6f 63 65 73 73 4d 65 73 73 61 |ts: processMessa|
|000000b0| 67 65 73 2d 64 66 63 35 30 35 39 34 2d 31 37 66 |ges-dfc50594-17f|
|000000c0| 34 2d 34 64 32 31 2d 38 38 36 62 2d 30 37 34 35 |4-4d21-886b-0745|
|000000d0| 62 34 62 61 39 65 36 34 3c 2f 43 6f 64 65 3e 0a |b4ba9e64</Code>.|
|000000e0| 20 20 20 20 20 20 20 20 3c 4d 65 73 73 61 67 65 |        <Message|
|000000f0| 3e 43 6f 6e 63 75 72 72 65 6e 74 20 61 63 63 65 |>Concurrent acce|
|00000100| 73 73 3a 20 51 75 65 75 65 20 61 6c 72 65 61 64 |ss: Queue alread|
|00000110| 79 20 65 78 69 73 74 73 3a 20 70 72 6f 63 65 73 |y exists: proces|
|00000120| 73 4d 65 73 73 61 67 65 73 2d 64 66 63 35 30 35 |sMessages-dfc505|
|00000130| 39 34 2d 31 37 66 34 2d 34 64 32 31 2d 38 38 36 |94-17f4-4d21-886|
|00000140| 62 2d 30 37 34 35 62 34 62 61 39 65 36 34 3b 20 |b-0745b4ba9e64; |
|00000150| 73 65 65 20 74 68 65 20 53 51 53 20 64 6f 63 73 |see the SQS docs|
|00000160| 2e 3c 2f 4d 65 73 73 61 67 65 3e 0a 20 20 20 20 |.</Message>.    |
|00000170| 20 20 20 20 3c 44 65 74 61 69 6c 2f 3e 0a 20 20 |    <Detail/>.  |
|00000180| 20 20 20 20 3c 2f 45 72 72 6f 72 3e 0a 20 20 20 |    </Error>.   |
|00000190| 20 20 20 3c 52 65 71 75 65 73 74 49 64 3e 30 30 |   <RequestId>00|
|000001a0| 30 30 30 30 30 30 2d 30 30 30 30 2d 30 30 30 30 |000000-0000-0000|
|000001b0| 2d 30 30 30 30 2d 30 30 30 30 30 30 30 30 30 30 |-0000-0000000000|
|000001c0| 30 30 3c 2f 52 65 71 75 65 73 74 49 64 3e 0a 20 |00</RequestId>. |
|000001d0| 20 20 20 3c 2f 45 72 72 6f 72 52 65 73 70 6f 6e |   </ErrorRespon|
|000001e0| 73 65 3e                                        |se>             |
+--------+-------------------------------------------------+----------------+
11:09:01.801  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.c.h.LastHttpContent] - Received LastHttpContent [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677]
11:09:01.801  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] READ COMPLETE
11:09:01.832  trace:[] span:[] [Test worker] ?[34mDEBUG?[m [s.a.a.c.i.ExecutionInterceptorChain] - Creating an interceptor chain that will apply interceptors in the following order: [software.amazon.awssdk.core.internal.interceptor.HttpChecksumRequiredInterceptor@23f9e716, software.amazon.awssdk.awscore.interceptor.HelpfulUnknownHostExceptionInterceptor@710c35b4, software.amazon.awssdk.services.sqs.internal.MessageMD5ChecksumInterceptor@6693624, software.amazon.awssdk.protocols.query.interceptor.QueryParametersToBodyInterceptor@3aa31a8f]
11:09:01.833  trace:[] span:[] [Test worker] ?[34mDEBUG?[m [s.a.a.c.i.ExecutionInterceptorChain] - Interceptor 'software.amazon.awssdk.protocols.query.interceptor.QueryParametersToBodyInterceptor@3aa31a8f' modified the message with its modifyHttpRequest method.
11:09:01.833  trace:[] span:[] [Test worker] ?[34mDEBUG?[m [s.a.a.request] - Sending Request: DefaultSdkHttpFullRequest(httpMethod=POST, protocol=http, host=127.0.0.1, port=35677, encodedPath=, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, User-Agent], queryParameters=[])
11:09:01.834  trace:[] span:[] [Test worker] ?[34mDEBUG?[m [s.a.a.a.s.Aws4Signer] - AWS4 String to sign: AWS4-HMAC-SHA256
20201120T190901Z
20201120/us-east-1/sqs/aws4_request
65970f3b7fcf31b877a1576262fa1274e5b1cea5e9f8cdad2cc99e5f84f75204
11:09:01.836  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] WRITE: software.amazon.awssdk.http.nio.netty.internal.NettyRequestExecutor$StreamedRequest(DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST / HTTP/1.1
Host: 127.0.0.1:35677
amz-sdk-invocation-id: 4d82efbf-150a-1f0a-f62f-250385cff49a
amz-sdk-retry: 0/0/
Authorization: AWS4-HMAC-SHA256 Credential=accesskey/20201120/us-east-1/sqs/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-retry;content-length;content-type;host;x-amz-date, Signature=b0e3e29919d8fbbe2bd5f6b71a87a4d3d095192910d453268a2ac0739081a8ae
Content-Length: 100
Content-Type: application/x-www-form-urlencoded; charset=utf-8
User-Agent: aws-sdk-java/2.15.26 Linux/4.4.0-122-generic OpenJDK_64-Bit_Server_VM/14.0.2+12-46 Java/14.0.2 vendor/Oracle_Corporation io/async http/NettyNio
X-Amz-Date: 20201120T190901Z)
11:09:01.836  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] FLUSH
11:09:01.837  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] FLUSH
11:09:01.837  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] WRITE: DefaultHttpContent(data: UnpooledHeapByteBuf(ridx: 0, widx: 100, cap: 100/100), decoderResult: success), 100B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 41 63 74 69 6f 6e 3d 43 72 65 61 74 65 51 75 65 |Action=CreateQue|
|00000010| 75 65 26 56 65 72 73 69 6f 6e 3d 32 30 31 32 2d |ue&Version=2012-|
|00000020| 31 31 2d 30 35 26 51 75 65 75 65 4e 61 6d 65 3d |11-05&QueueName=|
|00000030| 72 65 63 65 69 76 65 4d 65 73 73 61 67 65 73 2d |receiveMessages-|
|00000040| 62 33 39 62 61 66 35 37 2d 34 32 39 37 2d 34 37 |b39baf57-4297-47|
|00000050| 66 33 2d 62 35 33 35 2d 34 37 33 30 65 30 64 35 |f3-b535-4730e0d5|
|00000060| 36 61 62 30                                     |6ab0            |
+--------+-------------------------------------------------+----------------+
11:09:01.837  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] FLUSH
11:09:01.837  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] WRITE, EmptyLastHttpContent, 0B
11:09:01.838  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] FLUSH
11:09:01.862  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] READ: DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
Server: BaseHTTP/0.6 Python/3.8.2
Date: Fri, 20 Nov 2020 19:09:01 GMT
Content-Type: text/plain; charset=UTF-8
content-length: 466
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: HEAD,GET,PUT,POST,DELETE,OPTIONS,PATCH
Access-Control-Allow-Headers: authorization,content-type,content-md5,cache-control,x-amz-content-sha256,x-amz-date,x-amz-security-token,x-amz-user-agent,x-amz-target,x-amz-acl,x-amz-version-id,x-localstack-target,x-amz-tagging
Access-Control-Expose-Headers: x-amz-version-id
11:09:01.863  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [s.a.a.request] - Received successful response: 200
11:09:01.864  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] READ: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 466, cap: 466/466, unwrapped: PooledUnsafeDirectByteBuf(ridx: 998, widx: 998, cap: 16384)), decoderResult: success), 466B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 3c 43 72 65 61 74 65 51 75 65 75 65 52 65 73 70 |<CreateQueueResp|
|00000010| 6f 6e 73 65 20 78 6d 6c 6e 73 3d 22 68 74 74 70 |onse xmlns="http|
|00000020| 3a 2f 2f 71 75 65 75 65 2e 61 6d 61 7a 6f 6e 61 |://queue.amazona|
|00000030| 77 73 2e 63 6f 6d 2f 64 6f 63 2f 32 30 31 32 2d |ws.com/doc/2012-|
|00000040| 31 31 2d 30 35 2f 22 3e 0a 20 20 20 20 20 20 20 |11-05/">.       |
|00000050| 20 20 20 20 20 20 20 20 20 20 20 3c 43 72 65 61 |           <Crea|
|00000060| 74 65 51 75 65 75 65 52 65 73 75 6c 74 3e 0a 20 |teQueueResult>. |
|00000070| 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 |                |
|00000080| 20 20 20 3c 51 75 65 75 65 55 72 6c 3e 68 74 74 |   <QueueUrl>htt|
|00000090| 70 3a 2f 2f 6c 6f 63 61 6c 68 6f 73 74 3a 33 35 |p://localhost:35|
|000000a0| 36 37 37 2f 71 75 65 75 65 2f 72 65 63 65 69 76 |677/queue/receiv|
|000000b0| 65 4d 65 73 73 61 67 65 73 2d 62 33 39 62 61 66 |eMessages-b39baf|
|000000c0| 35 37 2d 34 32 39 37 2d 34 37 66 33 2d 62 35 33 |57-4297-47f3-b53|
|000000d0| 35 2d 34 37 33 30 65 30 64 35 36 61 62 30 3c 2f |5-4730e0d56ab0</|
|000000e0| 51 75 65 75 65 55 72 6c 3e 0a 20 20 20 20 20 20 |QueueUrl>.      |
|000000f0| 20 20 20 20 20 20 20 20 20 20 20 20 3c 2f 43 72 |            </Cr|
|00000100| 65 61 74 65 51 75 65 75 65 52 65 73 75 6c 74 3e |eateQueueResult>|
|00000110| 0a 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 |.               |
|00000120| 20 20 20 3c 52 65 73 70 6f 6e 73 65 4d 65 74 61 |   <ResponseMeta|
|00000130| 64 61 74 61 3e 0a 20 20 20 20 20 20 20 20 20 20 |data>.          |
|00000140| 20 20 20 20 20 20 20 20 20 20 3c 52 65 71 75 65 |          <Reque|
|00000150| 73 74 49 64 3e 30 30 30 30 30 30 30 30 2d 30 30 |stId>00000000-00|
|00000160| 30 30 2d 30 30 30 30 2d 30 30 30 30 2d 30 30 30 |00-0000-0000-000|
|00000170| 30 30 30 30 30 30 30 30 30 3c 2f 52 65 71 75 65 |000000000</Reque|
|00000180| 73 74 49 64 3e 0a 20 20 20 20 20 20 20 20 20 20 |stId>.          |
|00000190| 20 20 20 20 20 20 20 20 3c 2f 52 65 73 70 6f 6e |        </Respon|
|000001a0| 73 65 4d 65 74 61 64 61 74 61 3e 0a 20 20 20 20 |seMetadata>.    |
|000001b0| 20 20 20 20 20 20 20 20 20 20 20 20 3c 2f 43 72 |            </Cr|
|000001c0| 65 61 74 65 51 75 65 75 65 52 65 73 70 6f 6e 73 |eateQueueRespons|
|000001d0| 65 3e                                           |e>              |
+--------+-------------------------------------------------+----------------+
11:09:01.864  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.c.h.LastHttpContent] - Received LastHttpContent [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677]
11:09:01.864  trace:[] span:[] [aws-java-sdk-NettyEventLoop-1-5] ?[34mDEBUG?[m [i.n.h.l.LoggingHandler] - [id: 0xc91abb62, L:/127.0.0.1:57478 - R:/127.0.0.1:35677] READ COMPLETE

@amrynsky
Copy link
Author

amrynsky commented Dec 9, 2020

After further investigation, it's appeared to be an issue with LocalStack version used in our tests (0.11.1). Sometimes connection just hung. After upgrade to 0.12.2 everything works as expected.

@amrynsky amrynsky closed this as completed Dec 9, 2020
@github-actions
Copy link

github-actions bot commented Dec 9, 2020

⚠️COMMENT VISIBILITY WARNING⚠️

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.
If you wish to keep having a conversation with other community members under this issue feel free to do so.

@debora-ito
Copy link
Member

@amrynsky thank you for the follow-up.

aws-sdk-java-automation added a commit that referenced this issue Sep 15, 2022
@aws-sdk-java-automation
Merge pull request #2146 from aws/staging/05f6b59e-a924-4821-afe0-370…
47fb27b 
…b2a0f555e

Pull request: release <- staging/05f6b59e-a924-4821-afe0-370b2a0f555e
@sashjena sashjena mentioned this issue Nov 18, 2022
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug This issue is a bug. needs-triage This issue or PR still needs to be triaged.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@debora-ito @amrynsky