aws-sqs failed to set visibilityTimeout without any exception or warning

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

aws-sqs failed to set visibilityTimeout without any exception or warning

Qingyang Xu
Hi,
We have a micro service (multiple instances and each instance has multiple
consumers) on AWS that uses Camel aws-sqs to listen to a AWS sqs queue.
Our camel version is 2.24.0 and the aws-sqs config is
visibilityTimeout=300&extendMessageVisibility=true&maxMessagesPerPoll=5&con
currentConsumers=5.
Sometimes (less than 1%) we found our micro service duplicated to process
a message. And sometimes we can find a warning like this:
019-06-18 12:55:23.821 [Camel (camel-1) thread #7 - SqsTimeoutExtender]
WARN  o.a.c.c.a.sqs.SqsConsumer - Extending visibility window failed for
exchange Exchange[ID-i-00edba07f823c5496-1560852804975-0-254]. Will not
attempt to extend visibility further.
This exception will be ignored.
com.amazonaws.services.sqs.model.AmazonSQSException: Value
AQEB/3m4117WvFRRTVpLJVyLa9D0pbln3f2Y8x/0lgTfWEDd for parameter
ReceiptHandle is invalid. Reason: Message does not exist or is not
available for visibility timeout change. (Service: AmazonSQS; Status
Code: 400; Error Code: InvalidParameterValue; Request ID:
5531d38b-1253-59a1-a944-8609f3281568at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.handleErrorResponse(Ama
zonHttpClient.java:1638
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeOneRequest(Amazo
nHttpClient.java:1303
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHtt
pClient.java:1055
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.doExecute(AmazonHttpCli
ent.java:743
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeWithTimer(Amazon
HttpClient.java:717
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.execute(AmazonHttpClien
t.java:699
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.access$500(AmazonHttpCl
ient.java:667
at
com.amazonaws.http.AmazonHttpClient$RequestExecutionBuilderImpl.execute(Ama
zonHttpClient.java:649
at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:513
at
com.amazonaws.services.sqs.AmazonSQSClient.doInvoke(AmazonSQSClient.java:17
40
at
com.amazonaws.services.sqs.AmazonSQSClient.invoke(AmazonSQSClient.java:1716
at
com.amazonaws.services.sqs.AmazonSQSClient.executeChangeMessageVisibility(A
mazonSQSClient.java:518
at
com.amazonaws.services.sqs.AmazonSQSClient.changeMessageVisibility(AmazonSQ
SClient.java:494
at org.apache.camel.component.aws.sqs.SqsConsumer$TimeoutExtender.run
(SqsConsumer.java:327
(Executors.java:511
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access
$301(ScheduledThreadPoolExecutor.java:180
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run
(ScheduledThreadPoolExecutor.java:294
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1
149
at java.util.concurrent.ThreadPoolExecutor$Worker.run
(ThreadPoolExecutor.java:624
at java.lang.Thread.run
(Thread.java:748


I thought it is because Camel failed to extend the visibilityTimeout so
the message appeared in the queue and was picked up by another consumer. I
raised a AWS support ticket and got the logs from AWS like this:
1. Operation=SendMessage                  | RemoteIpAddress=52.213.250.143
| EndTime=Tue, 18 Jun 2019 12:51:18 UTC
2. Operation=ReceiveMessage              | RemoteIpAddress=52.208.226.232
| EndTime=Tue, 18 Jun 2019 12:51:18 UTC | VisibilityTimeout=60
3. Operation=ReceiveMessage              | RemoteIpAddress=52.209.137.230
| EndTime=Tue, 18 Jun 2019 12:52:19 UTC | VisibilityTimeout=60
4. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
EndTime=Tue, 18 Jun 2019 12:52:49 UTC | VisibilityTimeout=90
5. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
EndTime=Tue, 18 Jun 2019 12:53:49 UTC | VisibilityTimeout=90
6. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
EndTime=Tue, 18 Jun 2019 12:54:49 UTC | VisibilityTimeout=90
7. Operation=ChangeMessageVisibility | RemoteIpAddress=52.208.226.232 |
EndTime=Tue, 18 Jun 2019 12:55:23 UTC | VisibilityTimeout=90
8. Operation=DeleteMessage                | RemoteIpAddress=52.209.137.230
| EndTime=Tue, 18 Jun 2019 12:55:23 UTC
9. Operation=ChangeMessageVisibility | RemoteIpAddress=52.208.226.232 |
EndTime=Tue, 18 Jun 2019 12:56:23 UTC | VisibilityTimeout=90
10. Operation=DeleteMessage                |
RemoteIpAddress=52.208.226.232 | EndTime=Tue, 18 Jun 2019 12:56:57 UTC

We can see the message was picked up by the first
consumer(RemoteIpAddress=52.208.226.232) but it didn't extend the
visibilityTimeout, so after 60 seconds the message was picked up by
another consumer(RemoteIpAddress=52.209.137.230) which extended the
VisibilityTimeout as usual. This happened without any warning and
exception. We saw the warning because somehow after about 4 minutes the
first consumer tried to extend the VisibilityTimeout after the message was
deleted. Sometimes this happened completely
silently.

This happened a couple of times every week. Is it because of something
wrong with the threads (concurrentConsumers=5) which has problem to
schedule the VisibilityTimeout extension? Has anyone seen this before?

Many thanks,
Qingyang Xu

Reply | Threaded
Open this post in threaded view
|

Re: aws-sqs failed to set visibilityTimeout without any exception or warning

Andrea Cosentino-2
Do you have a simple reproducer for this?

--
Andrea Cosentino 
----------------------------------
Apache Camel PMC Chair
Apache Karaf Committer
Apache Servicemix PMC Member
Email: [hidden email]
Twitter: @oscerd2
Github: oscerd






On Tuesday, June 25, 2019, 5:11:05 PM GMT+2, Qingyang Xu <[hidden email]> wrote:





Hi,
We have a micro service (multiple instances and each instance has multiple
consumers) on AWS that uses Camel aws-sqs to listen to a AWS sqs queue.
Our camel version is 2.24.0 and the aws-sqs config is
visibilityTimeout=300&extendMessageVisibility=true&maxMessagesPerPoll=5&con
currentConsumers=5.
Sometimes (less than 1%) we found our micro service duplicated to process
a message. And sometimes we can find a warning like this:
019-06-18 12:55:23.821 [Camel (camel-1) thread #7 - SqsTimeoutExtender]
WARN  o.a.c.c.a.sqs.SqsConsumer - Extending visibility window failed for
exchange Exchange[ID-i-00edba07f823c5496-1560852804975-0-254]. Will not
attempt to extend visibility further.
This exception will be ignored.
com.amazonaws.services.sqs.model.AmazonSQSException: Value
AQEB/3m4117WvFRRTVpLJVyLa9D0pbln3f2Y8x/0lgTfWEDd for parameter
ReceiptHandle is invalid. Reason: Message does not exist or is not
available for visibility timeout change. (Service: AmazonSQS; Status
Code: 400; Error Code: InvalidParameterValue; Request ID:
5531d38b-1253-59a1-a944-8609f3281568at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.handleErrorResponse(Ama
zonHttpClient.java:1638
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeOneRequest(Amazo
nHttpClient.java:1303
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHtt
pClient.java:1055
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.doExecute(AmazonHttpCli
ent.java:743
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeWithTimer(Amazon
HttpClient.java:717
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.execute(AmazonHttpClien
t.java:699
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.access$500(AmazonHttpCl
ient.java:667
at
com.amazonaws.http.AmazonHttpClient$RequestExecutionBuilderImpl.execute(Ama
zonHttpClient.java:649
at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:513
at
com.amazonaws.services.sqs.AmazonSQSClient.doInvoke(AmazonSQSClient.java:17
40
at
com.amazonaws.services.sqs.AmazonSQSClient.invoke(AmazonSQSClient.java:1716
at
com.amazonaws.services.sqs.AmazonSQSClient.executeChangeMessageVisibility(A
mazonSQSClient.java:518
at
com.amazonaws.services.sqs.AmazonSQSClient.changeMessageVisibility(AmazonSQ
SClient.java:494
at org.apache.camel.component.aws.sqs.SqsConsumer$TimeoutExtender.run
(SqsConsumer.java:327
(Executors.java:511
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access
$301(ScheduledThreadPoolExecutor.java:180
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run
(ScheduledThreadPoolExecutor.java:294
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1
149
at java.util.concurrent.ThreadPoolExecutor$Worker.run
(ThreadPoolExecutor.java:624
at java.lang.Thread.run
(Thread.java:748


I thought it is because Camel failed to extend the visibilityTimeout so
the message appeared in the queue and was picked up by another consumer. I
raised a AWS support ticket and got the logs from AWS like this:
1. Operation=SendMessage                  | RemoteIpAddress=52.213.250.143
| EndTime=Tue, 18 Jun 2019 12:51:18 UTC
2. Operation=ReceiveMessage              | RemoteIpAddress=52.208.226.232
| EndTime=Tue, 18 Jun 2019 12:51:18 UTC | VisibilityTimeout=60
3. Operation=ReceiveMessage              | RemoteIpAddress=52.209.137.230
| EndTime=Tue, 18 Jun 2019 12:52:19 UTC | VisibilityTimeout=60
4. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
EndTime=Tue, 18 Jun 2019 12:52:49 UTC | VisibilityTimeout=90
5. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
EndTime=Tue, 18 Jun 2019 12:53:49 UTC | VisibilityTimeout=90
6. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
EndTime=Tue, 18 Jun 2019 12:54:49 UTC | VisibilityTimeout=90
7. Operation=ChangeMessageVisibility | RemoteIpAddress=52.208.226.232 |
EndTime=Tue, 18 Jun 2019 12:55:23 UTC | VisibilityTimeout=90
8. Operation=DeleteMessage                | RemoteIpAddress=52.209.137.230
| EndTime=Tue, 18 Jun 2019 12:55:23 UTC
9. Operation=ChangeMessageVisibility | RemoteIpAddress=52.208.226.232 |
EndTime=Tue, 18 Jun 2019 12:56:23 UTC | VisibilityTimeout=90
10. Operation=DeleteMessage                |
RemoteIpAddress=52.208.226.232 | EndTime=Tue, 18 Jun 2019 12:56:57 UTC

We can see the message was picked up by the first
consumer(RemoteIpAddress=52.208.226.232) but it didn't extend the
visibilityTimeout, so after 60 seconds the message was picked up by
another consumer(RemoteIpAddress=52.209.137.230) which extended the
VisibilityTimeout as usual. This happened without any warning and
exception. We saw the warning because somehow after about 4 minutes the
first consumer tried to extend the VisibilityTimeout after the message was
deleted. Sometimes this happened completely
silently.

This happened a couple of times every week. Is it because of something
wrong with the threads (concurrentConsumers=5) which has problem to
schedule the VisibilityTimeout extension? Has anyone seen this before?

Many thanks,
Qingyang Xu
Reply | Threaded
Open this post in threaded view
|

Re: aws-sqs failed to set visibilityTimeout without any exception or warning

Qingyang Xu
Hi,
Thank you for your reply. I don't have a simple reproducer. It happens
about once in 200 messages. It is rare but it does happen almost everyday.
That's quite annoying :(

On 01/07/2019, 14:46, "Andrea Cosentino" <[hidden email]>
wrote:

>Do you have a simple reproducer for this?
>
>--
>Andrea Cosentino
>----------------------------------
>Apache Camel PMC Chair
>Apache Karaf Committer
>Apache Servicemix PMC Member
>Email: [hidden email]
>Twitter: @oscerd2
>Github: oscerd
>
>
>
>
>
>
>On Tuesday, June 25, 2019, 5:11:05 PM GMT+2, Qingyang Xu
><[hidden email]> wrote:
>
>
>
>
>
>Hi,
>We have a micro service (multiple instances and each instance has multiple
>consumers) on AWS that uses Camel aws-sqs to listen to a AWS sqs queue.
>Our camel version is 2.24.0 and the aws-sqs config is
>visibilityTimeout=300&extendMessageVisibility=true&maxMessagesPerPoll=5&co
>n
>currentConsumers=5.
>Sometimes (less than 1%) we found our micro service duplicated to process
>a message. And sometimes we can find a warning like this:
>019-06-18 12:55:23.821 [Camel (camel-1) thread #7 - SqsTimeoutExtender]
>WARN  o.a.c.c.a.sqs.SqsConsumer - Extending visibility window failed for
>exchange Exchange[ID-i-00edba07f823c5496-1560852804975-0-254]. Will not
>attempt to extend visibility further.
>This exception will be ignored.
>com.amazonaws.services.sqs.model.AmazonSQSException: Value
>AQEB/3m4117WvFRRTVpLJVyLa9D0pbln3f2Y8x/0lgTfWEDd for parameter
>ReceiptHandle is invalid. Reason: Message does not exist or is not
>available for visibility timeout change. (Service: AmazonSQS; Status
>Code: 400; Error Code: InvalidParameterValue; Request ID:
>5531d38b-1253-59a1-a944-8609f3281568at
>com.amazonaws.http.AmazonHttpClient$RequestExecutor.handleErrorResponse(Am
>a
>zonHttpClient.java:1638
>at
>com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeOneRequest(Amaz
>o
>nHttpClient.java:1303
>at
>com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHt
>t
>pClient.java:1055
>at
>com.amazonaws.http.AmazonHttpClient$RequestExecutor.doExecute(AmazonHttpCl
>i
>ent.java:743
>at
>com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeWithTimer(Amazo
>n
>HttpClient.java:717
>at
>com.amazonaws.http.AmazonHttpClient$RequestExecutor.execute(AmazonHttpClie
>n
>t.java:699
>at
>com.amazonaws.http.AmazonHttpClient$RequestExecutor.access$500(AmazonHttpC
>l
>ient.java:667
>at
>com.amazonaws.http.AmazonHttpClient$RequestExecutionBuilderImpl.execute(Am
>a
>zonHttpClient.java:649
>at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:513
>at
>com.amazonaws.services.sqs.AmazonSQSClient.doInvoke(AmazonSQSClient.java:1
>7
>40
>at
>com.amazonaws.services.sqs.AmazonSQSClient.invoke(AmazonSQSClient.java:171
>6
>at
>com.amazonaws.services.sqs.AmazonSQSClient.executeChangeMessageVisibility(
>A
>mazonSQSClient.java:518
>at
>com.amazonaws.services.sqs.AmazonSQSClient.changeMessageVisibility(AmazonS
>Q
>SClient.java:494
>at org.apache.camel.component.aws.sqs.SqsConsumer$TimeoutExtender.run
>(SqsConsumer.java:327
>(Executors.java:511
>at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308
>at
>java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.acces
>s
>$301(ScheduledThreadPoolExecutor.java:180
>at
>java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run
>(ScheduledThreadPoolExecutor.java:294
>at
>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>1
>149
>at java.util.concurrent.ThreadPoolExecutor$Worker.run
>(ThreadPoolExecutor.java:624
>at java.lang.Thread.run
>(Thread.java:748
>
>
>I thought it is because Camel failed to extend the visibilityTimeout so
>the message appeared in the queue and was picked up by another consumer. I
>raised a AWS support ticket and got the logs from AWS like this:
>1. Operation=SendMessage                  | RemoteIpAddress=52.213.250.143
>| EndTime=Tue, 18 Jun 2019 12:51:18 UTC
>2. Operation=ReceiveMessage              | RemoteIpAddress=52.208.226.232
>| EndTime=Tue, 18 Jun 2019 12:51:18 UTC | VisibilityTimeout=60
>3. Operation=ReceiveMessage              | RemoteIpAddress=52.209.137.230
>| EndTime=Tue, 18 Jun 2019 12:52:19 UTC | VisibilityTimeout=60
>4. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
>EndTime=Tue, 18 Jun 2019 12:52:49 UTC | VisibilityTimeout=90
>5. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
>EndTime=Tue, 18 Jun 2019 12:53:49 UTC | VisibilityTimeout=90
>6. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
>EndTime=Tue, 18 Jun 2019 12:54:49 UTC | VisibilityTimeout=90
>7. Operation=ChangeMessageVisibility | RemoteIpAddress=52.208.226.232 |
>EndTime=Tue, 18 Jun 2019 12:55:23 UTC | VisibilityTimeout=90
>8. Operation=DeleteMessage                | RemoteIpAddress=52.209.137.230
>| EndTime=Tue, 18 Jun 2019 12:55:23 UTC
>9. Operation=ChangeMessageVisibility | RemoteIpAddress=52.208.226.232 |
>EndTime=Tue, 18 Jun 2019 12:56:23 UTC | VisibilityTimeout=90
>10. Operation=DeleteMessage                |
>RemoteIpAddress=52.208.226.232 | EndTime=Tue, 18 Jun 2019 12:56:57 UTC
>
>We can see the message was picked up by the first
>consumer(RemoteIpAddress=52.208.226.232) but it didn't extend the
>visibilityTimeout, so after 60 seconds the message was picked up by
>another consumer(RemoteIpAddress=52.209.137.230) which extended the
>VisibilityTimeout as usual. This happened without any warning and
>exception. We saw the warning because somehow after about 4 minutes the
>first consumer tried to extend the VisibilityTimeout after the message was
>deleted. Sometimes this happened completely
>silently.
>
>This happened a couple of times every week. Is it because of something
>wrong with the threads (concurrentConsumers=5) which has problem to
>schedule the VisibilityTimeout extension? Has anyone seen this before?
>
>Many thanks,
>Qingyang Xu

Reply | Threaded
Open this post in threaded view
|

Re: aws-sqs failed to set visibilityTimeout without any exception or warning

Qingyang Xu
From the logs provided by the AWS support, I can see these 2 issues:
1) Sometimes Camel doesn't set the visibilityTimeout(or Camel sends the
request but AWS doesn't set it) and Camel doesn't catch this information.
2) Sometimes AWS fails to extend the visibilityTimeout and Camel catch it.
Camel throw out a WARNING. My question is why Camel doesn't retry to
extend the visibilityTimeout when this happened? And I am not sure whether
Camel should throw out an Exception rather than a Warning because it can
cause the duplication and real problem.


On 02/07/2019, 11:22, "Qingyang Xu" <[hidden email]> wrote:

>Hi,
>Thank you for your reply. I don't have a simple reproducer. It happens
>about once in 200 messages. It is rare but it does happen almost everyday.
>That's quite annoying :(
>
>On 01/07/2019, 14:46, "Andrea Cosentino" <[hidden email]>
>wrote:
>
>>Do you have a simple reproducer for this?
>>
>>--
>>Andrea Cosentino
>>----------------------------------
>>Apache Camel PMC Chair
>>Apache Karaf Committer
>>Apache Servicemix PMC Member
>>Email: [hidden email]
>>Twitter: @oscerd2
>>Github: oscerd
>>
>>
>>
>>
>>
>>
>>On Tuesday, June 25, 2019, 5:11:05 PM GMT+2, Qingyang Xu
>><[hidden email]> wrote:
>>
>>
>>
>>
>>
>>Hi,
>>We have a micro service (multiple instances and each instance has
>>multiple
>>consumers) on AWS that uses Camel aws-sqs to listen to a AWS sqs queue.
>>Our camel version is 2.24.0 and the aws-sqs config is
>>visibilityTimeout=300&extendMessageVisibility=true&maxMessagesPerPoll=5&c
>>o
>>n
>>currentConsumers=5.
>>Sometimes (less than 1%) we found our micro service duplicated to process
>>a message. And sometimes we can find a warning like this:
>>019-06-18 12:55:23.821 [Camel (camel-1) thread #7 - SqsTimeoutExtender]
>>WARN  o.a.c.c.a.sqs.SqsConsumer - Extending visibility window failed for
>>exchange Exchange[ID-i-00edba07f823c5496-1560852804975-0-254]. Will not
>>attempt to extend visibility further.
>>This exception will be ignored.
>>com.amazonaws.services.sqs.model.AmazonSQSException: Value
>>AQEB/3m4117WvFRRTVpLJVyLa9D0pbln3f2Y8x/0lgTfWEDd for parameter
>>ReceiptHandle is invalid. Reason: Message does not exist or is not
>>available for visibility timeout change. (Service: AmazonSQS; Status
>>Code: 400; Error Code: InvalidParameterValue; Request ID:
>>5531d38b-1253-59a1-a944-8609f3281568at
>>com.amazonaws.http.AmazonHttpClient$RequestExecutor.handleErrorResponse(A
>>m
>>a
>>zonHttpClient.java:1638
>>at
>>com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeOneRequest(Ama
>>z
>>o
>>nHttpClient.java:1303
>>at
>>com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonH
>>t
>>t
>>pClient.java:1055
>>at
>>com.amazonaws.http.AmazonHttpClient$RequestExecutor.doExecute(AmazonHttpC
>>l
>>i
>>ent.java:743
>>at
>>com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeWithTimer(Amaz
>>o
>>n
>>HttpClient.java:717
>>at
>>com.amazonaws.http.AmazonHttpClient$RequestExecutor.execute(AmazonHttpCli
>>e
>>n
>>t.java:699
>>at
>>com.amazonaws.http.AmazonHttpClient$RequestExecutor.access$500(AmazonHttp
>>C
>>l
>>ient.java:667
>>at
>>com.amazonaws.http.AmazonHttpClient$RequestExecutionBuilderImpl.execute(A
>>m
>>a
>>zonHttpClient.java:649
>>at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:513
>>at
>>com.amazonaws.services.sqs.AmazonSQSClient.doInvoke(AmazonSQSClient.java:
>>1
>>7
>>40
>>at
>>com.amazonaws.services.sqs.AmazonSQSClient.invoke(AmazonSQSClient.java:17
>>1
>>6
>>at
>>com.amazonaws.services.sqs.AmazonSQSClient.executeChangeMessageVisibility
>>(
>>A
>>mazonSQSClient.java:518
>>at
>>com.amazonaws.services.sqs.AmazonSQSClient.changeMessageVisibility(Amazon
>>S
>>Q
>>SClient.java:494
>>at org.apache.camel.component.aws.sqs.SqsConsumer$TimeoutExtender.run
>>(SqsConsumer.java:327
>>(Executors.java:511
>>at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308
>>at
>>java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.acce
>>s
>>s
>>$301(ScheduledThreadPoolExecutor.java:180
>>at
>>java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run
>>(ScheduledThreadPoolExecutor.java:294
>>at
>>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java
>>:
>>1
>>149
>>at java.util.concurrent.ThreadPoolExecutor$Worker.run
>>(ThreadPoolExecutor.java:624
>>at java.lang.Thread.run
>>(Thread.java:748
>>
>>
>>I thought it is because Camel failed to extend the visibilityTimeout so
>>the message appeared in the queue and was picked up by another consumer.
>>I
>>raised a AWS support ticket and got the logs from AWS like this:
>>1. Operation=SendMessage                  |
>>RemoteIpAddress=52.213.250.143
>>| EndTime=Tue, 18 Jun 2019 12:51:18 UTC
>>2. Operation=ReceiveMessage              | RemoteIpAddress=52.208.226.232
>>| EndTime=Tue, 18 Jun 2019 12:51:18 UTC | VisibilityTimeout=60
>>3. Operation=ReceiveMessage              | RemoteIpAddress=52.209.137.230
>>| EndTime=Tue, 18 Jun 2019 12:52:19 UTC | VisibilityTimeout=60
>>4. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
>>EndTime=Tue, 18 Jun 2019 12:52:49 UTC | VisibilityTimeout=90
>>5. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
>>EndTime=Tue, 18 Jun 2019 12:53:49 UTC | VisibilityTimeout=90
>>6. Operation=ChangeMessageVisibility | RemoteIpAddress=52.209.137.230 |
>>EndTime=Tue, 18 Jun 2019 12:54:49 UTC | VisibilityTimeout=90
>>7. Operation=ChangeMessageVisibility | RemoteIpAddress=52.208.226.232 |
>>EndTime=Tue, 18 Jun 2019 12:55:23 UTC | VisibilityTimeout=90
>>8. Operation=DeleteMessage                |
>>RemoteIpAddress=52.209.137.230
>>| EndTime=Tue, 18 Jun 2019 12:55:23 UTC
>>9. Operation=ChangeMessageVisibility | RemoteIpAddress=52.208.226.232 |
>>EndTime=Tue, 18 Jun 2019 12:56:23 UTC | VisibilityTimeout=90
>>10. Operation=DeleteMessage                |
>>RemoteIpAddress=52.208.226.232 | EndTime=Tue, 18 Jun 2019 12:56:57 UTC
>>
>>We can see the message was picked up by the first
>>consumer(RemoteIpAddress=52.208.226.232) but it didn't extend the
>>visibilityTimeout, so after 60 seconds the message was picked up by
>>another consumer(RemoteIpAddress=52.209.137.230) which extended the
>>VisibilityTimeout as usual. This happened without any warning and
>>exception. We saw the warning because somehow after about 4 minutes the
>>first consumer tried to extend the VisibilityTimeout after the message
>>was
>>deleted. Sometimes this happened completely
>>silently.
>>
>>This happened a couple of times every week. Is it because of something
>>wrong with the threads (concurrentConsumers=5) which has problem to
>>schedule the VisibilityTimeout extension? Has anyone seen this before?
>>
>>Many thanks,
>>Qingyang Xu
>