Uploaded image for project: 'Camel'
  1. Camel
  2. CAMEL-17156

camel-aws - Cancelling "Extending visibility window" while processing completed causes interruption exception

    XMLWordPrintableJSON

Details

    • Improvement
    • Status: Resolved
    • Minor
    • Resolution: Fixed
    • 3.11.3, 3.12.0
    • 3.13.0, 3.11.4
    • camel-aws2
    • Unknown

    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

      Attachments

        Issue Links

          Activity

            People

              Unassigned Unassigned
              smox Simon Rasmussen
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: