Aws-sdk-go: Possible loss of confirmed messages in SQS Client Library

[jugalde-r7]

Version of AWS SDK for Go?

1.16.2

Version of Go (go version)?

1.10.1

What issue did you see?

We believe through a series of errors we've witnessed in our production environment, and replicated with the supplied testing script linked below (results included), that we are witnessing cases where the go sdk appears to successfully submit a message, including a response with a seemingly-valid message id, but then that message is never found when receiving from the queue, thus appearing as though it has been lost.

How we found the problem

How we found the problem
We have a setup where we use two SQS queues in tandem which are governed by RESTful API - A worker will request work to perform over rest from queue 1, where we send along the Receipt Handle of the original message, and when the worker completes, it includes the Receipt Handle so that the handler can delete the original message, before it re-enqueues the results onto a queue 2 for a third process to pick up. We continue to track the original receipt handle as a means of verifying where the message originated from within our own logging, and we see the lost message getting enqueued without errors. We do this by including the original ReceiptHandle in the body of the message itself. We are aware that the ReceiptHandle will change for each receipt of the message, which is not what our problem is.
The problem we're running into is that this third process never sees the message by way of tracking the receipt handle from inside of our own message body, however we have no indication of any errors from SQS when publishing the message. This indicates to us that either the go library, or SQS itself, is dropping committed messages.
It's worth noting that this overall seems to be exceptionally rare. In reproducing the issue for the steps below, it would take up to an hour of near constant SQS access before we were able to detect a "lost" message this way.

Steps to reproduce

https://gist.github.com/jugalde-r7/70abdab946fba5b96326429a88f981b4
To replicate, edit queue.go to use your credentials in the config, and url1 and url2 to be queue1 and queue2 that have the following settings:
Queue1 has VisibilityTimeout=30 seconds, MaxRetentionPeriod=14 day, MaximumMessageSize=256KB, and ReceiveMessageWaitTime=5 seconds
Queue2 has VisibilityTimeout=5 minutes, MaxRetentionPeriod=4 day, MaximumMessageSize=256KB, and ReceiveMessageWaitTime=0 seconds
Once that is all setup, simply do $go run queue.go

Typically it takes an hour or two for the test to yield a dropped message. Though we did not include the debug logging in the above gist for security reasons, we had the debug logging on and saw no errors in that logging

Next Steps

After testing this for almost a week, I'm fairly confident that the issue is somewhere in the go library or in SQS itself.I'm happy to help further diagnose this, as currently this is causing us to rethink our strategies about relying on SQS and forcing us to implement backup approaches to persisting some of these messages, which we'd prefer not to do. I would also be happy to accept any feedback possible on improving or iterating on my test script, as I want to be positive that we're not missing anything when we reproduce this.

[diehlaws]

Thanks for reaching out to us about this @jugalde-r7. I'm able to reproduce this on my end with the provided code, however looking at the resultant debug output it looks like this behavior is originating from the service rather than the AWS SDK for Go. I've reached out to the SQS team internally about this so it can be further investigated from the service end, and will update the issue once we have additional information.

[diehlaws]

Thank you for your patience in this matter @jugalde-r7. The service team has responded suggesting that the behavior you're seeing is caused by messages being added to the queues immediately after they're getting purged, and have suggested adding a delay of at least 1 minute between purging these queues and beginning to add more messages.

Per the PurgeQueue documentation page, this API call takes up to 60 seconds to complete - messages sent to the queue before you call PurgeQueue might be received but are deleted within the next minute, and messages sent to the queue after you call PurgeQueue might be deleted while the queue is being purged.

I hope this helps eliminate the behavior you're seeing between your SQS queues, however if it does not please do let us know so we can further investigate this behavior.

[jugalde-r7]

@diehlaws thanks for following up. This explains what we were seeing, good to know.

[diehlaws]

No problem! I'll close out the issue since it sounds like this solves the behavior you're seeing. Please don't hesitate to reach back out if you continue to see this behavior and we'll re-open the issue to further investigate this.