NServiceBus6 delayed recovery not delaying

Question

Without getting to terribly detailed about the problem we are trying to solve I have the need to make NServiceBus do 1 of 5 things, but I'm currently just trying to get the first one to work. That is that given a reply back from a web API call we want to have a delayed retry, immediate retry, give up, cancel or start over. The delayed retry looks like it is best done using the custom recoverability so I followed this: Custom Recoverability Policy and came up with this

public static class UpdateEndpointConfiguration
{
    public static void ConfigureEndpointForUpdateVocxoSurveyApi(this EndpointConfiguration configuration)
    {
        var recoverabilitySettings = configuration.Recoverability();
        recoverabilitySettings.CustomPolicy(SetCustomPolicy);
    }

    private static RecoverabilityAction SetCustomPolicy(RecoverabilityConfig config, ErrorContext context)
    {
        var action = DefaultRecoverabilityPolicy.Invoke(config, context);
        if (context.Exception is DelayedRetryException delayedRetryException)
        {
            return RecoverabilityAction.DelayedRetry(TimeSpan.FromSeconds(delayedRetryException.DelayRetryTimeoutSeconds));
        }
        return action;
    }
}

Then as a test I made a simple message so I don't have to force the web api to do silly things:

public class ForceDelayRetry : ICommand
{
    public int DelayInSeconds { get; set; }
}

and then "handle it"

public class TestRequestHandler : IHandleMessages<ForceDelayRetry>
{
    private static readonly ILog Log = LogManager.GetLogger(typeof(TestRequestHandler));

    public async Task Handle(ForceDelayRetry message, IMessageHandlerContext context)
    {
        Log.Info($"Start processing {nameof(ForceDelayRetry)}");
        var handleUpdateRequestFailure = IoC.Get<HandleUpdateRequestFailure>();
        await handleUpdateRequestFailure.HandleFailedRequest(new UpdateRequestFailed
        {
            DelayRetryTimeoutSeconds = message.DelayInSeconds,
            Message = $"For testing purposes I am forcing a delayed retry of {message.DelayInSeconds} second(s)",
            RecoveryAction = RecoveryAction.DelayRetry
        }, context, 12345);
        Log.Info($"Finished processing {nameof(ForceDelayRetry)}");
    }
}

I start the service up and in the span of about 1.5 minutes the two test messages were processed 5,400 times approximately. The log message looks similar to this (ommitted stack trace for brevity)

20180601 15:28:47 :INFO  [14] TestRequestHandler Start processing ForceDelayRetry
20180601 15:28:47 :WARN  [22] NServiceBus.RecoverabilityExecutor Delayed Retry will reschedule message '690f317e-5be0-4511-88b9-a8f2013ac219' after a delay of 00:00:01 because of an exception:
20180601 15:28:47 :INFO  [14] TestRequestHandler Start processing ForceDelayRetry
20180601 15:28:47 :WARN  [14] NServiceBus.RecoverabilityExecutor Delayed Retry will reschedule message '7443e553-b558-486d-b7e9-a8f2014088d5' after a delay of 00:00:01 because of an exception:
20180601 15:28:47 :INFO  [4] TestRequestHandler Start processing ForceDelayRetry
20180601 15:28:47 :WARN  [14] NServiceBus.RecoverabilityExecutor Delayed Retry will reschedule message '690f317e-5be0-4511-88b9-a8f2013ac219' after a delay of 00:00:01 because of an exception:
20180601 15:28:47 :INFO  [14] TestRequestHandler Start processing ForceDelayRetry
20180601 15:28:47 :WARN  [14] NServiceBus.RecoverabilityExecutor Delayed Retry will reschedule message '7443e553-b558-486d-b7e9-a8f2014088d5' after a delay of 00:00:01 because of an exception:

so either i'm doing something wrong, or there is a bug but I don't know which. Can anyone see what the problem is?

edit

here is the method handleUpdateRequestFailure.HandleFailedRequest

    public async Task HandleFailedRequest(UpdateRequestFailed failure, IMessageHandlerContext context, long messageSurveyId)
    {
        switch (failure.RecoveryAction)
        {
            case RecoveryAction.DelayRetry:
                Log.InfoFormat("Recovery action is {0} because {1}. Retrying in {2} seconds", failure.RecoveryAction, failure.Message, failure.DelayRetryTimeoutSeconds);
                await context.Send(_auditLogEntryCreator.Create(_logger.MessageIsBeingDelayRetried, messageSurveyId));
                throw new DelayedRetryException(failure.DelayRetryTimeoutSeconds);
            case RecoveryAction.EndPipelineRequest:
            case RecoveryAction.RestartPipelineRequest:
            case RecoveryAction.RetryImmediate:
            case RecoveryAction.RouteToErrorQueue:
                break;
        }
    }

and as the comment pointed out I would have infinite retries on my message which I found out too, but here is the updated logic for it

    private static RecoverabilityAction SetCustomPolicy(RecoverabilityConfig config, ErrorContext context)
    {
        var action = DefaultRecoverabilityPolicy.Invoke(config, context);
        if (context.Exception is DelayedRetryException delayedRetryException)
        {
            if (config.Delayed.MaxNumberOfRetries > context.DelayedDeliveriesPerformed)
                return RecoverabilityAction.DelayedRetry(TimeSpan.FromSeconds(delayedRetryException.DelayRetryTimeoutSeconds));
        }
        return action;
    }

Answer 1

That is that given a reply back from a web API call we want to have a delayed retry, immediate retry, give up, cancel or start over. The delayed retry looks like it is best done using the custom recoverability

I'm not sure I understand what you're trying to achieve, beyond what NServiceBus already offers? Let immediate and delayed retry do what it is best at: do the actual retries.

And if you want more functionality, use a saga. Let the saga orchestrate the process and have a separate handler do the actual call to the external service. The saga can then, based on the replies of this handler, decide if it should stop, continue, take an alternate path, etc.

If you want to discuss this further I suggest you contact us at [email protected] and we can set up a conference call and show you how we'd do this.