shashank created CAMEL-25809:
--------------------------------
Summary: camel-aws2-sqs - with extendMessageVisibility=true and
maxMessagesPerPoll > 10, the first extension can come after the visibility
timeout ran out when the poll waited for a long-polling receive
Key: CAMEL-25809
URL: https://issues.apache.org/jira/browse/CAMEL-25809
Project: Camel
Issue Type: Bug
Components: camel-aws2
Reporter: shashank
Assignee: shashank
With {{extendMessageVisibility=true}} the SQS consumer keeps the messages it
processes invisible: its {{TimeoutExtender}} runs every {{max(1,
visibilityTimeout / 2)}} seconds and extends a message whose deadline falls
before its next run. The deadline is 80 % of {{visibilityTimeout}} counted from
the moment the message is registered with the extender, at the start of
{{processBatch}} (since CAMEL-25700; {{Sqs2Consumer}} lines 142-147 and 532 on
main 62c9a3ebe409). SQS counts the visibility timeout from the receive.
Normally the two are milliseconds apart. Not when a poll sends several receive
requests: with {{maxMessagesPerPoll}} greater than 10, {{PollingTask}} sends
one {{ReceiveMessage}} per 10 messages concurrently and joins them
({{CompletableFuture.get}}), so the batch starts only when the last request
returned. With long polling ({{waitTimeSeconds}}), a request that finds no more
messages waits up to {{waitTimeSeconds}}, while the messages returned by the
first request are already counting down.
With a gap L between the receive and the start of the batch, the first
extension comes between {{L + 0.3 x visibilityTimeout}} and {{L + 0.8 x
visibilityTimeout}} after the receive (depending on the phase of the extender).
It is late as soon as L is more than about 20 % of {{visibilityTimeout}}:
||visibilityTimeout||waitTimeSeconds (gap L)||first extension after the
receive||late for||
|30|20|29 to 44 s|14 of 15 phases|
|30|10|19 to 34 s|4 of 15 phases|
|60|20|38 to 68 s|8 of 30 phases|
|10|5|8 to 13 s|3 of 5 phases|
A late message becomes visible again while the route still processes it, and
another consumer (another instance, or {{concurrentConsumers}} > 1) receives
it: it is processed twice, which is what {{extendMessageVisibility}} is for.
The extender's {{ChangeMessageVisibility}} then fails ({{MessageNotInflight}} /
{{ReceiptHandleIsInvalid}}) and is only logged. This was noted as a follow-up
in the review of CAMEL-25700 (apache/camel#27985).
Trigger: {{extendMessageVisibility=true}}, {{maxMessagesPerPoll}} > 10, long
polling with {{waitTimeSeconds}} (or the queue's
{{ReceiveMessageWaitTimeSeconds}}) above about 20 % of {{visibilityTimeout}},
and a queue that does not fill every receive request of a poll at once (a quiet
or moderately busy queue). With the default {{maxMessagesPerPoll}}, or without
long polling, the gap stays small and nothing changes.
*Fix*: the messages of a poll are dated from the start of the poll (which is
never after their receive), and when one of them is due before the next
scheduled run of the extender, the extender runs at once (on its own single
thread, so it does not overlap a scheduled run). Extensions after the first are
unchanged. Cost: with long polling, one extra {{ChangeMessageVisibilityBatch}}
call for a batch whose poll waited long.
*Tests*: new {{SqsConsumerExtendMessageVisibilityLongPollTest}} with the
module's {{AmazonSQSClientMock}} (no AWS):
{{maxMessagesPerPoll=20&visibilityTimeout=4&extendMessageVisibility=true}}, one
request of the poll returns the message at once, the other waits 3 s (a long
poll on a queue with no more messages), the route holds the message until it
was extended. It asserts that the first {{ChangeMessageVisibilityBatch}} for
the message comes less than 4 s after its receive. On main it fails:
{{Expecting actual: 4995L to be less than: 4000L}} (4998 ms on the reruns).
With the fix it passes; camel-aws2-sqs unit tests: 78 run, 0 failures.
*How it was found*: a Z3 model of the extension schedule vs the visibility
window (period {{max(1, V/2)}} s, deadline registration + 0.8 V, gap L between
receive and registration): no counterexample for L = 0, a late first extension
once L exceeds about 0.2 V; then the JUnit test above.
*Affected*: main, camel-4.23.x, camel-4.22.x and camel-4.18.x (same deadline,
period and concurrent receive requests; on those branches without CAMEL-25700 a
message is registered only when its turn in the batch comes, so the gap is
larger; read, not run).
_Filed with Claude Code on behalf of allthingssecurity._
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
