Debug a visibility-timeout redelivery

Use this when a message was delivered again before the first consumer finished with it, or a delete failed with ReceiptHandleIsInvalid.

1Step 1: Know what Trailbeam infers#

SQS has no event for "the visibility timeout ran out". Trailbeam sees only the receives around it. Trailbeam adds an inferred Visibility timeout expired step (type: "visibility_timeout_expired") between two receives when:

• both are on the same queue, and
• the later one has a higher receive_count (ApproximateReceiveCount) than the earlier one.

A delete that SQS accepted for the earlier delivery does not prevent the expiry. The later receive shows that the delete came too late.

Two receives with the same receive count get no expiry. That is an at-least-once duplicate, not a timeout. If the count jumps by more than one, Trailbeam also adds Deliveries not observed with the number of missing receives. It adds the same step when the first receive it sees on the source queue already has a count above 1.

The expiry carries after_delivery, before_delivery, queue, a window and a reason. Its earlier anchor is the receive of after_delivery, unless a ChangeMessageVisibility that SQS accepted for that delivery is proven to come before the redelivery. Then the latest such change is the anchor, because it restarted the timer. window.from is the anchor's start, window.to is the redelivery's end.

2Step 2: Read the reason#

The reason is picked from what Trailbeam has for the earlier delivery, in this order:

Only changes and deletes with result: "ok" count. A rejected visibility change does not restart the timer and is ignored.

3Step 3: Match the pattern#

A slow consumer#

This is the demo's slow message on ElasticMQ, which rejects a delete with an earlier delivery's handle. Amazon SQS accepts that delete, so the same run there shows delivery 1's delete as result ok, status stale_handle, and the expiry's reason becomes the "came too late" one, because an accepted delete of delivery 1 now exists.

A released message#

The consumer gave the message back on purpose. The expiry's window starts at the visibility change, not at receive 1.

A heartbeat that stopped#

The consumer extended the timeout twice, then stopped extending (it crashed or hung). The expiry is placed after the last accepted extension.

4Step 4: Read the delete status#

Every deleted event has result and status. delivery is the delivery whose receipt handle was used, found by the receipt-handle hash join, not by time.

error_code is what the hooks recorded:

Prevent it#

Set the queue's visibility timeout above your slowest normal run. If runs vary, extend the timeout while working and stop when done. Each extension is recorded as Visibility changed, so the timeline shows exactly when the heartbeat stopped.

import threading

def run_with_heartbeat(sqs, queue_url, message, work, extend_s=30, every_s=20):
    done = threading.Event()

    def beat():
        while not done.wait(every_s):
            sqs.change_message_visibility(QueueUrl=queue_url, ReceiptHandle=message["ReceiptHandle"],
                                          VisibilityTimeout=extend_s)

    t = threading.Thread(target=beat, daemon=True)
    t.start()
    try:
        work(message)
    finally:
        done.set()
        t.join()
    sqs.delete_message(QueueUrl=queue_url, ReceiptHandle=message["ReceiptHandle"])

const { ChangeMessageVisibilityCommand, DeleteMessageCommand } = require('@aws-sdk/client-sqs');

async function runWithHeartbeat(sqs, queueUrl, message, work, extendS = 30, everyMs = 20000) {
  const timer = setInterval(() => {
    sqs.send(new ChangeMessageVisibilityCommand({
      QueueUrl: queueUrl, ReceiptHandle: message.ReceiptHandle, VisibilityTimeout: extendS,
    })).catch(() => {});
  }, everyMs);
  try {
    await work(message);
  } finally {
    clearInterval(timer);
  }
  await sqs.send(new DeleteMessageCommand({ QueueUrl: queueUrl, ReceiptHandle: message.ReceiptHandle }));
}

Both clients must be instrumented (trailbeam.boto.install() or trailbeam.instrument(client)) for the extensions to appear.

To reproduce all three patterns locally, run the Quickstart demo. Its orders queue has a 10 s visibility timeout. retry_once messages are released with a visibility change to 0, and slow messages run for 13 s.

Related#

• Find out why a message ran twice
• Receipt handles
• Ordering
• Span contract: delete and change visibility