[CAMEL-17156] camel-aws - Cancelling "Extending visibility window" while processing completed causes interruption exception

• Type: Improvement
• Status: Resolved
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 3.11.3, 3.12.0
• Fix Version/s: 3.13.0, 3.11.4
• Component/s: camel-aws2
• Labels: sqs
• Estimated Complexity: Unknown
• Assignee: Unassigned
• Reporter: Simon Rasmussen
• Created: 01/Nov/21 12:06
• Updated: 03/Nov/21 08:56
• Resolved: 02/Nov/21 19:12

Description

The issue happens when the Sqs2Consomer has `extendMessageVisibility` enabled. At that point, Sqs2Consumer will create an extend task which is allowed to interrupt running task:

 exchange.adapt(ExtendedExchange.class).addOnCompletion(new Synchronization() {
                    @Override
                    public void onComplete(Exchange exchange) {
                        cancelExtender(exchange);
                    }

                    @Override
                    public void onFailure(Exchange exchange) {
                        cancelExtender(exchange);
                    }

                    private void cancelExtender(Exchange exchange) {
                        // cancel task as we are done
                        LOG.trace("Processing done so cancelling TimeoutExtender task for exchangeId: {}",
                                exchange.getExchangeId());
                        scheduledFuture.cancel(true);
                    }
                });

This causes below stack trace.

	
2021-11-01 08:51:45.970  WARN 10 --- [TimeoutExtender] o.a.c.component.aws2.sqs.Sqs2Consumer    : [] Extending visibility window failed for exchange Exchange[CE30770DB50EE42-0000000000000718]. Will not attempt to extend visibility further. This exception will be ignored.

software.amazon.awssdk.core.exception.AbortedException: Thread was interrupted
	at software.amazon.awssdk.core.exception.AbortedException$BuilderImpl.build(AbortedException.java:84) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.exception.AbortedException.create(AbortedException.java:38) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.handleInterruptedException(ApiCallAttemptTimeoutTrackingStage.java:142) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.translatePipelineException(ApiCallAttemptTimeoutTrackingStage.java:106) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:90) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:42) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage.execute(TimeoutExceptionHandlingStage.java:78) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage.execute(TimeoutExceptionHandlingStage.java:40) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage.execute(ApiCallAttemptMetricCollectionStage.java:50) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage.execute(ApiCallAttemptMetricCollectionStage.java:36) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.execute(RetryableStage.java:80) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.execute(RetryableStage.java:36) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.StreamManagingStage.execute(StreamManagingStage.java:56) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.StreamManagingStage.execute(StreamManagingStage.java:36) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.executeWithTimer(ApiCallTimeoutTrackingStage.java:80) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:60) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:42) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage.execute(ApiCallMetricCollectionStage.java:48) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage.execute(ApiCallMetricCollectionStage.java:31) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:37) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:26) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.AmazonSyncHttpClient$RequestExecutionBuilderImpl.execute(AmazonSyncHttpClient.java:193) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.invoke(BaseSyncClientHandler.java:103) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.doExecute(BaseSyncClientHandler.java:167) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.lambda$execute$1(BaseSyncClientHandler.java:82) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.measureApiCallSuccess(BaseSyncClientHandler.java:175) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.execute(BaseSyncClientHandler.java:76) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.client.handler.SdkSyncClientHandler.execute(SdkSyncClientHandler.java:45) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.awscore.client.handler.AwsSyncClientHandler.execute(AwsSyncClientHandler.java:56) ~[aws-core-2.17.42.jar:na]
	at software.amazon.awssdk.services.sqs.DefaultSqsClient.changeMessageVisibility(DefaultSqsClient.java:348) ~[sqs-2.17.42.jar:na]
	at org.apache.camel.component.aws2.sqs.Sqs2Consumer$TimeoutExtender.run(Sqs2Consumer.java:381) ~[camel-aws2-sqs-3.12.0.jar:3.12.0]
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na]
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na]
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
Caused by: software.amazon.awssdk.core.exception.SdkInterruptedException: null
	at software.amazon.awssdk.core.internal.http.InterruptMonitor.checkInterrupted(InterruptMonitor.java:40) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AfterTransmissionExecutionInterceptorsStage.execute(AfterTransmissionExecutionInterceptorsStage.java:34) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.AfterTransmissionExecutionInterceptorsStage.execute(AfterTransmissionExecutionInterceptorsStage.java:28) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206) ~[sdk-core-2.17.42.jar:na]
	at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:73) ~[sdk-core-2.17.42.jar:na]
	... 35 common frames omitted

There are 2 solutions to this:
1: Do not interrupt the running task, this will allow the messageExtension request to complete, and no exception is thrown as this is handled gracefully already by catching `ReceiptHandleIsInvalidException`
2: Catch the `AbortedException` in `TimeoutExtender#run`.

I have been testing option #1 for a few hours now, and it seem like an acceptable solution

Issue Links

• links to: GitHub Pull Request #6362