Client Configuration of TimeOuts(Socket/Connection) not applied in AmazonSqs Client

[ashish04121988]

Describe the bug

0

We are using SQS in our Java Spring Boot Project. While publishing messages to SQS, most of the messages are processed in <=300ms. However, some requests took more than 50 seconds. Upon initial investigation, we found that the SDK retries failed requests, taking 50 seconds to mark them as failures before initiating retries. In most cases, the message is reprocessed within <=300ms after the initial retry (resulting in a total time of around 50,300ms).

We aim to minimize the request time to 10 seconds, ensuring that retries happen after a maximum of 10 seconds in case of failure. We've already attempted some configurations.

Expected Behavior

After applying ClientCingurations, timeouts should happen basis configurations provided.

@bean
public ClientConfiguration getClientConfig() {
ClientConfiguration clientConfig = new ClientConfiguration();
clientConfig = clientConfig.withSocketTimeout(7000);
clientConfig = clientConfig.withRequestTimeout(9000);
clientConfig = clientConfig.withConnectionTimeout(11000);
clientConfig = clientConfig.withClientExecutionTimeout(13000);
return clientConfig;
}

@Bean
public AmazonSQS amazonSqs() {
    String region = !StringUtils.isEmpty(sqsRegion) ? sqsRegion : AWSConfigConstants.AWS_SQS_REGION;
    return AmazonSQSClientBuilder.standard()
            .withRegion(region)
            .withClientConfiguration(getClientConfig())
            .withCredentials(InstanceProfileCredentialsProvider.createAsyncRefreshingProvider(true)).build();
}

@Autowired
private AmazonSQS amazonSQS;
private String queueName=DEFAULT_QUEUE_NAME;

public void send(String message){
long startMillis1 = System.currentTimeMillis();
SendMessageResult result = amazonSQS.sendMessage(queueName,message);
long startMillis2 = System.currentTimeMillis();
long totalTimeTaken=(startMillis2-startMillis1);
}

Current Behavior

Still timeouts taking 50 secs and after that it is retrying.

2023-06-23 13:30:30.873 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG com.amazonaws.request.executeOneRequest(1288) - Sending Request: POST https://sqs.ap-south-1.amazonaws.com/ /444121746292/PROD_OA_COMMUNICATION_H 2023-06-23 13:30:30.874 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.auth.AWS4Signer.debug(33) - AWS4 Canonical Request: '"POST /444121746292/PROD_OA_COMMUNICATION_H

amz-sdk-invocation-id:e7a34898-7848-0029-5fd0-a284535470da amz-sdk-request:ttl=20230623T080120Z;attempt=1;max=4 amz-sdk-retry:0/0/500 host:sqs.ap-south-1.amazonaws.com user-agent:aws-sdk-java/1.12.490 Linux/5.10.165-143.735.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/17.0.7+7-alpine-r1 java/17.0.7 vendor/Alpine cfg/retry-mode/legacy AmazonSQSBufferedAsyncClient/1.12.490 x-amz-date:20230623T080030Z

amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;host;user-agent;x-amz-date;x-amz-security-token fbcd61f597391a4e7e0a9eb1a917624d698d4fc3fd154d30e1b29a2242dbb9a1" 2023-06-23 13:30:30.874 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.auth.AWS4Signer.debug(33) - AWS4 String to Sign: '"AWS4-HMAC-SHA256 20230623T080030Z

2023-06-23 13:30:30.874 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.auth.AWS4Signer.debug(33) - AWS4 String to Sign: '"AWS4-HMAC-SHA256 20230623T080030Z 20230623/ap-south-1/sqs/aws4_request 3971c6f53f806d34ef5fef6e85e6306a3bb22ae0fcff46ffafd7b5830770b04e"

2023-06-23 13:31:20.924 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.internal.SdkSSLSocket.shutdownOutput(76) - shutting down output of sqs.ap-south-1.amazonaws.com/15.207.13.23:443 2023-06-23 13:31:20.924 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.internal.SdkSSLSocket.shutdownInput(69) - shutting down input of sqs.ap-south-1.amazonaws.com/15.207.13.23:443 2023-06-23 13:31:20.925 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.internal.SdkSSLSocket.close(62) - closing sqs.ap-south-1.amazonaws.com/15.207.13.23:443 2023-06-23 13:31:20.925 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.http.AmazonHttpClient.handleRetryableException(1227) - Unable to execute HTTP request: Read timed out Request will be retried.

After 50 secs it got timed out and then going for next retry

2023-06-23 13:31:20.925 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG com.amazonaws.request.executeOneRequest(1288) - Retrying Request: POST https://sqs.ap-south-1.amazonaws.com/ /444121746292/PROD_OA_COMMUNICATION_H 2023-06-23 13:31:20.925 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.http.AmazonHttpClient.doPauseBeforeRetry(1915) - Retriable error detected, will retry in 100ms, attempt number: 0 2023-06-23 13:31:21.025 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.auth.AWS4Signer.debug(33) - AWS4 Canonical Request: '"POST /444121746292/PROD_OA_COMMUNICATION_H

amz-sdk-invocation-id:e7a34898-7848-0029-5fd0-a284535470da amz-sdk-request:ttl=20230623T080211Z;attempt=2;max=4 amz-sdk-retry:1/100/495 host:sqs.ap-south-1.amazonaws.com user-agent:aws-sdk-java/1.12.490 Linux/5.10.165-143.735.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/17.0.7+7-alpine-r1 java/17.0.7 vendor/Alpine cfg/retry-mode/legacy AmazonSQSBufferedAsyncClient/1.12.490 x-amz-date:20230623T080121Z

amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;host;user-agent;x-amz-date;x-amz-security-token fbcd61f597391a4e7e0a9eb1a917624d698d4fc3fd154d30e1b29a2242dbb9a1" 2023-06-23 13:31:21.025 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.auth.AWS4Signer.debug(33) - AWS4 String to Sign: '"AWS4-HMAC-SHA256 20230623T080121Z 20230623/ap-south-1/sqs/aws4_request 903819bdcc9dc60794362b8465aa30176334ba9edc58026200fb4a65554ead62" 2023-06-23 13:31:21.033 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.r.ClockSkewAdjuster.getServerDate(179) - Reported server date (from 'Date' header): Fri, 23 Jun 2023 08:01:21 GMT 2023-06-23 13:31:21.033 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG com.amazonaws.request.handle(86) - Received successful response: 200, AWS Request ID: 7ceaac46-35c2-5967-acd0-f149665367ff 2023-06-23 13:31:21.033 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG com.amazonaws.requestId.logHeaderRequestId(138) - x-amzn-RequestId: 7ceaac46-35c2-5967-acd0-f149665367ff 2023-06-23 13:31:21.034 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.s.s.MessageMD5ChecksumHandler.calculateMessageBodyMd5(196) - Message body: {"id":null,"eventCode":"otp_verify","emailId":null,"mobileNumber":"8696089862","customerId":null,"modelAttributes":{"Location":"Android","Result":"success"},"userId":8696089862,"attachments":[],"tokens":null,"commMode":null,"delayInSeconds":0,"templateId":null,"commTransactionId":null,"documents":null,"ekitRequired":null,"processedDocUrls":{},"additionalAttributes":{},"missingAttributes":null,"byPassApp":false,"async":true,"cc":null,"bcc":null,"requestId":"49b19216-8b87-4cff-bff4-1fd644c9071d"} 2023-06-23 13:31:21.034 [] [] [SQSQueueBufferWorkerThread-16] [] [] [] [] DEBUG c.a.s.s.MessageMD5ChecksumHandler.calculateMessageBodyMd5(207) - Expected MD5 of message body: 82cb93d74c3133cc3f0057aca36fb331

Reproduction Steps

@bean
public ClientConfiguration getClientConfig() {
ClientConfiguration clientConfig = new ClientConfiguration();
clientConfig = clientConfig.withSocketTimeout(7000);
clientConfig = clientConfig.withRequestTimeout(9000);
clientConfig = clientConfig.withConnectionTimeout(11000);
clientConfig = clientConfig.withClientExecutionTimeout(13000);
return clientConfig;
}

@Bean
public AmazonSQS amazonSqs() {
    String region = !StringUtils.isEmpty(sqsRegion) ? sqsRegion : AWSConfigConstants.AWS_SQS_REGION;
    return AmazonSQSClientBuilder.standard()
            .withRegion(region)
            .withClientConfiguration(getClientConfig())
            .withCredentials(InstanceProfileCredentialsProvider.createAsyncRefreshingProvider(true)).build();
}

@Autowired
private AmazonSQS amazonSQS;
private String queueName=DEFAULT_QUEUE_NAME;

public void send(String message){
long startMillis1 = System.currentTimeMillis();
SendMessageResult result = amazonSQS.sendMessage(queueName,message);
long startMillis2 = System.currentTimeMillis();
long totalTimeTaken=(startMillis2-startMillis1);
}

Possible Solution

No response

Additional Information/Context

No response

AWS Java SDK version used

com.amazonaws aws-java-sdk-sqs 1.12.262

JDK version used

Java17

Operating System and version

Linux

[debora-ito]

@ashish04121988 You shared the x-amz-security-token in your logs so I removed them. Please rotate your AWS credentials as soon as possible.

We'll take a look at the issue shortly.

[ashish04121988]

@debora-ito Any update on the issue?