SQS VisibilityTimeout behaviour

Platform
1

Hello guys
Happy to join community. I have a question regarding the VisibilityTimeout behaviour.
I use sqs in testcontainers with localstack image and it seems like comand below doesn’t work at all.
localStack.execInContainer(“awslocal”, “sqs”, “set-queue-attributes”, “–queue-url”, sqsEndpoint + “/” + JOB_QUEUE_NAME, “–attributes”, “VisibilityTimeout”, “43200”);

I have the next flow:

  • put the message in queue
  • read it using @SqsListener(value = “${queueName}”, deletionPolicy = SqsMessageDeletionPolicy.ON_SUCCESS) (awspring version: 2.3.2 + the latest testcontainers version and the latest localstack image version)
  • process event
  • and then there’s the part that probably influences that behaviour. This is verification step in test.

I use awaitility to verify my assertations:

given()
                .ignoreException(IndexOutOfBoundsException.class)
                .await()
                .timeout(5, TimeUnit.SECONDS)
                .atMost(3, TimeUnit.MINUTES)
                .pollInterval(500, TimeUnit.MILLISECONDS)
                .untilAsserted(() -> {
                    verifyWiremockCallOne();
                    verifyWiremockCallTwo();
                    verifyWiremockCallThree(22);
                    verifyWiremockCallFour();

                    verifyFirstQueueIteration();
                    verifySecondQueueIteration();
                    verifyInputQueueIteration();
                });

When the verifycation block is running my consumer get the event second time and start executing process from scratch but how can it happen if I set the biggest possible delay before next consume?

I think that while the conditions in the untilAsserted block are being checked (checking for calls to wiremock, receiving messages from the queues where I send the corresponding messages) the message is sent to processing again because the test has not been completed and the process is still alive.

It is also strange that my message was not instantly deleted from the queue after processing, because I have this parameter deletionPolicy = SqsMessageDeletionPolicy.ON_SUCCESS.

2

Hey @akulik512!

I just tested this to make sure the set-queue-attributes command works correctly, and it seems to work fine using just aws cli commands.

Here’s what I did:

awslocal sqs create-queue --queue-name test-queue                                             
{
    "QueueUrl": "http://localhost:4566/000000000000/test-queue"
}

awslocal sqs set-queue-attributes --queue-url http://localhost:4566/000000000000/test-queue --attributes VisibilityTimeout=43200

awslocal sqs send-message --queue-url http://localhost:4566/000000000000/test-queue --message-body "hello"
{
    "MD5OfMessageBody": "5d41402abc4b2a76b9719d911017c592",
    "MessageId": "93ff2d59-bead-4c17-bdbf-585c4b9a8de0"
}

awslocal sqs receive-message --queue-url http://localhost:4566/000000000000/test-queue
{
    "Messages": [
        {
            "MessageId": "93ff2d59-bead-4c17-bdbf-585c4b9a8de0",
            "ReceiptHandle": "YWQ1MGI1Y2QtYmE0OS00MzFhLThmMGEtMjczODYxZTYwNTMzIGFybjphd3M6c3FzOnVzLWVhc3QtMTowMDAwMDAwMDAwMDA6dGVzdC1xdWV1ZSA5M2ZmMmQ1OS1iZWFkLTRjMTctYmRiZi01ODVjNGI5YThkZTAgMTY5MTY4NzA0Mi4xNTg2MjA2",
            "MD5OfBody": "5d41402abc4b2a76b9719d911017c592",
            "Body": "hello"
        }
    ]
}

In the localstack log output I can see:

2023-08-10T19:03:32.282  INFO --- [   asgi_gw_0] localstack.request.aws     : AWS sqs.CreateQueue => 200
2023-08-10T19:03:34.555  INFO --- [   asgi_gw_0] localstack.request.aws     : AWS sqs.SetQueueAttributes => 200
2023-08-10T19:03:45.675  INFO --- [   asgi_gw_0] localstack.request.aws     : AWS sqs.SendMessage => 200
2023-08-10T19:04:02.158 DEBUG --- [   asgi_gw_0] l.services.sqs.models      : de-queued message SqsMessage(id=93ff2d59-bead-4c17-bdbf-585c4b9a8de0,group=None) from arn:aws:sqs:us-east-1:000000000000:test-queue
2023-08-10T19:04:02.159  INFO --- [   asgi_gw_0] localstack.request.aws     : AWS sqs.ReceiveMessage => 200

and then nothing else. OK I didn’t wait 12 hours :wink: but normally you would see something like:

2023-08-10T19:06:15.597 DEBUG --- [-functhread5] l.services.sqs.models      : re-queueing inflight messages SqsMessage(id=d33eed4f-db59-40c3-a424-54735ae515ad,group=None) into queue arn:aws:sqs:us-east-1:000000000000:test-queue

in the logs when the message gets re-queued after the visibility timeout expired.

With the information we have so far I can’t really say much. I’d suggest running localstack with DEBUG=1 and looking into the logs to see what’s going on. In particular I would double check whether the message deletion works correctly!

3

I figured out that the problem was on my side.
Thank you very much for your attention!