[jira] [Resolved] (CAMEL-25809) 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

["Claus Ibsen (Jira)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/CAMEL-25809?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Claus Ibsen resolved CAMEL-25809.
---------------------------------
    Resolution: Fixed

Fixed by https://github.com/apache/camel/pull/28201 (merged to main for 4.24.0).

_Claude Code on behalf of davsclaus_

> 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
>            Priority: Major
>             Fix For: 4.24.0
>
>
> 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)