Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

The visibility timeout is being set incorrect to include the "elapsedSeconds" #269

Closed
charlescapps opened this issue Aug 13, 2021 · 3 comments
Labels

Comments

@charlescapps
Copy link
Contributor

Describe the bug
I noticed that for a long-running message handler with a visibilityTimeout of 2 minutes, the visibility of the message was incorrectly being set to 1 full hour in the future (for a job that had been running for 1 hour).

From perusing the code, it's clear that the bug is due to a misunderstanding of how ChangeVisibilityTimeout functions.
The SQS Developer Guide Visibility Timeout Docs state clearly:

For example, if the default timeout for a queue is 60 seconds, 15 seconds have elapsed since you received the message, and you send a ChangeMessageVisibility call with VisibilityTimeout set to 10 seconds, the 10 seconds begin to count from the time that you make the ChangeMessageVisibility call. Thus, any attempt to change the visibility timeout or to delete that message 10 seconds after you initially change the visibility timeout (a total of 25 seconds) might result in an error.

Also -

Note
The new timeout period takes effect from the time you call the ChangeMessageVisibility action. ...

However, the code in consumer.ts is incorrectly including the total elapsed time in the new visibility timeout:

return this.changeVisabilityTimeout(message, elapsedSeconds + this.visibilityTimeout);

To Reproduce
Steps to reproduce the behaviour:

  1. Create a message handler that takes a long time to run, and then fails to ACK the message e.g.
const handleMessage = (async (message: AWS.SQS.Message): Promise<void> => {
  const tenMinutesMillis = 10*60*1000;
  return new Promise(resolve => setTimeout(resolve, tenMinutesMillis)).then(() => {
    throw Error("Message failed to process!");
  });
}
  1. Use a much shorter visibilityTimeout, e.g. 30 seconds
  2. Run your consumer:
const consumerOptions: ConsumerOptions = {
      queueUrl: "...",
      visibilityTimeout: 30,
      handleMessage,
      sqs,
    };
return Consumer.create(consumerOptions);
  1. Enqueue a message in your SQS queue
  2. Wait for it to run for 10 minutes, then throw an error

Expected behaviour
After the failure, your SQS consumer can process the message again after the 30 second visibilityTimeout passes.

Actual behavior
The message isn't visible for a full additional 10 minutes & 30 seconds, which is the total elapsed time so far added on to the time when the request to ChangeVisibilityTimeout is made.

screenshots
Large 1 hour gap in our logs where the message wasn't reprocessed during testing.

Screen Shot 2021-08-13 at 2 59 53 PM

Additional context
This fix is really easy - just delete the elapsedSeconds being added on to the visibility timeout. I'll put up a pull request.

charlescapps added a commit to charlescapps/sqs-consumer that referenced this issue Aug 13, 2021
tomwinnington added a commit that referenced this issue Aug 19, 2021
…-visibility-timeout

Issue #269 - fix the call to ChangeVisibilityTimeout to not include elapsed seconds
@charlescapps
Copy link
Contributor Author

Hi @tomwinnington , any chance we could publish a new version to npm? I don't know what the process is for that for this repo, but it looks like maintainers trigger it.

@tomwinnington
Copy link
Contributor

Hi @charlescapps, I can do this today for you.

@charlescapps
Copy link
Contributor Author

Thank you kindly for releasing that, @tomwinnington . Have a great day.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants