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).

질문됨 4년 전557회 조회
2개 답변
0

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

답변함 4년 전
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.

답변함 4년 전

로그인하지 않았습니다. 로그인해야 답변을 게시할 수 있습니다.

좋은 답변은 질문에 명확하게 답하고 건설적인 피드백을 제공하며 질문자의 전문적인 성장을 장려합니다.

질문 답변하기에 대한 가이드라인

관련 콘텐츠