By using AWS re:Post, you agree to the AWS re:Post Terms of Use
AWS re:Postre:Post

ChangeMessageVisibility - existing receipt handle reported as expired

0

In my JMS listener connected to an SQS queue I call setVisibilityTimeout to extend the timeout and allow for a long-running to finish as suggested in https://docs.aws.amazon.com/AWSSimpleQueueService/latest/SQSDeveloperGuide/sqs-visibility-timeout.html#configuring-visibility-timeout.
Unfortunately, most of the time I get an error response (Reason: The receipt handle has expired). visibilityTimeout for the queue is set to 300s and extending the visibility is the first thing that is done after receiving a message so there is no way that the handle is already expired.
What is more interesting, after receiving such an error response, JMS calls setVisibilityTimeout again on the same receipt handle to change the timeout to 0 and make the message available for other workers to process. This second call is successful. It looks like the seemingly expired message handle is working again after just few milliseconds.

I turned on debug logs for com.amazonaws.request and it can be clearly seen below:

DEBUG 2020-08-12T17:40:19,981 \[ConsumerPrefetchThread-1] \[] \[com.amazonaws.request] "Sending Request: POST https://sqs.eu-central-1.amazonaws.com //queue.fifo Parameters: ({"Action":\["ReceiveMessage"],"Version":\["2012-11-05"],"AttributeName.1":\["All"],"MessageAttributeName.1":\["All"],"MessageAttributeName.2":\["SQSLargePayloadSize"],"MaxNumberOfMessages":\["1"],"WaitTimeSeconds":\["20"],"ReceiveRequestAttemptId":\["0bbb2c42-94d5-4a0b-8aca-4f2dce9058f2"]}Headers: (User-Agent: aws-sdk-java/1.11.228 Linux/5.4.0-42-generic OpenJDK_64-Bit_Server_VM/11.0.8+10-LTS java/11.0.8 /SQS Java Messaging Client v1.0 AmazonSQSExtendedClient/1.11.228, amz-sdk-invocation-id: 7593448a-2867-a2e7-907b-d893015d58cf, ) "
DEBUG 2020-08-12T17:40:23,708 \[asyncExecutor-1] \[e76d55a4-0664-43c1-9c0c-b1458df62b4f] \[com.amazonaws.request] "Sending Request: POST https://sqs.eu-central-1.amazonaws.com //queue.fifo Parameters: ({"Action":\["ChangeMessageVisibility"],"Version":\["2012-11-05"],"ReceiptHandle":\["AQEBGqvUSuWJKtF4l1k9G2cC46jhcQQsLZJlQNCxIU2m8c_Iqo5fii/0u8W4tnk58golmCN0OynwsOFCEWw3pjs_fHL8/81X81360H/2qQB8/SQqoe6qCfXbxD8/9ATRP32Go3DHpMy93nb9RQ2_1Wqe9nLoxV2iIZxLChlhLcIYs6Le2z6gSXcfQykoj9N17sAY0lQ6d7qzZ3S3mmsc5QFlSlxY4_KrQp93guMbIS51gbyNrj_F_N2e9nM4lf5LWrelE8BhL6WDwIBtSGNk_DN4eLI8shTX1L1T/1DDpErysBblDFtJQ8iQxWC5ayufedCD"],"VisibilityTimeout":\["600"]}Headers: (User-Agent: aws-sdk-java/1.11.228 Linux/5.4.0-42-generic OpenJDK_64-Bit_Server_VM/11.0.8_10-LTS java/11.0.8, amz-sdk-invocation-id: ca2d4cbb-f6b4-e896-d7b2-5d41d01a5eef, ) "
EBUG 2020-08-12T17:40:23,764 \[asyncExecutor-1] \[e76d55a4-0664-43c1-9c0c-b1458df62b4f] \[com.amazonaws.request] "Received error response: com.amazonaws.services.sqs.model.AmazonSQSException: Value AQEBGqvUSuWJKtF4l1k9G2cC46jhcQQsLZJlQNCxIU2m8c_Iqo5fii/0u8W4tnk58golmCN0OynwsOFCEWw3pjs_fHL8/81X81360H/2qQB8/SQqoe6qCfXbxD8/9ATRP32Go3DHpMy93nb9RQ2_1Wqe9nLoxV2iIZxLChlhLcIYs6Le2z6gSXcfQykoj9N17sAY0lQ6d7qzZ3S3mmsc5QFlSlxY4_KrQp93guMbIS51gbyNrj_F_N2e9nM4lf5LWrelE8BhL6WDwIBtSGNk+DN4eLI8shTX1L1T/1DDpErysBblDFtJQ8iQxWC5ayufedCD for parameter ReceiptHandle is invalid. Reason: The receipt handle has expired. (Service: AmazonSQS; Status Code: 400; Error Code: InvalidParameterValue; Request ID: 560fb9f9-f79c-5f44-a21f-ee57dc5b5832)"

DEBUG 2020-08-12T17:40:23,766 \[asyncExecutor-1] \[] \[com.amazonaws.request] "Sending Request: POST https://sqs.eu-central-1.amazonaws.com /************/queue.fifo Parameters: ({"Action":\["ChangeMessageVisibilityBatch"],"Version":\["2012-11-05"],"ChangeMessageVisibilityBatchRequestEntry.1.Id":\["0"],"ChangeMessageVisibilityBatchRequestEntry.1.ReceiptHandle":\["AQEBGqvUSuWJKtF4l1k9G2cC46jhcQQsLZJlQNCxIU2m8c_Iqo5fii/0u8W4tnk58golmCN0OynwsOFCEWw3pjs_fHL8/81X81360H/2qQB8/SQqoe6qCfXbxD8/9ATRP32Go3DHpMy93nb9RQ2_1Wqe9nLoxV2iIZxLChlhLcIYs6Le2z6gSXcfQykoj9N17sAY0lQ6d7qzZ3S3mmsc5QFlSlxY4_KrQp93guMbIS51gbyNrj_F_N2e9nM4lf5LWrelE8BhL6WDwIBtSGNk_DN4eLI8shTX1L1T/1DDpErysBblDFtJQ8iQxWC5ayufedCD"],"ChangeMessageVisibilityBatchRequestEntry.1.VisibilityTimeout":\["0"]}Headers: (User-Agent: aws-sdk-java/1.11.228 Linux/5.4.0-42-generic OpenJDK_64-Bit_Server_VM/11.0.8_10-LTS java/11.0.8 /SQS Java Messaging Client v1.0, amz-sdk-invocation-id: 9ddb4853-99e1-bda6-218e-e6646ec23a61, ) "
DEBUG 2020-08-12T17:40:23,788 \[StartThread] \[e76d55a4-0664-43c1-9c0c-b1458df62b4f] \[com.amazonaws.request] "Received successful response: 200, AWS Request ID: 532e3d49-5764-5176-b2fa-6ae77ca370e5"

Did anyone encounter similar problems? For me it seems like the SQS API is quite unreliable even with a really small load (less than one message per second).

Topics
ServerlessApplication Integration
Tags
Amazon Simple Queue Service
Language
English
maciejmucha
asked 4 years ago548 views
2 Answers
0

Attaching logs, because the file was truncated in the original post.

maciejmucha
answered 4 years ago
0

The problem was caused by the Amazon SQS Java Messaging Library prefetching. By default the library prefetches one message into internal buffer and if the processing of the first message takes longer than the visibilityTimeout it may expire before it reaches the listener.
My conclusion about the second call was wrong - according to https://docs.aws.amazon.com/cli/latest/reference/sqs/change-message-visibility-batch.html this call always return 200, so it probably failed as well.
Solution for me is to disable prefetching by using ProviderConfiguration().withNumberOfMessagesToPrefetch(0) to create the configuration.

maciejmucha
answered 4 years ago

You are not logged in. Log in to post an answer.

A good answer clearly answers the question and provides constructive feedback and encourages professional growth in the question asker.

Guidelines for Answering Questions

Relevant content