Cannot settle messages if the lock is renewed for more than 17 minutes

[jsquire]

Issue Transfer

This issue has been transferred from the Azure SDK for .NET repository, #40339.

Please be aware that @ygavrishov is the author of the original issue and include them for any questions or replies.

Details

Description

Somehow ServiceBusProcessor cannot complete messages if processing lasts longer than 20 minutes. The same result is received with ServiceBusReceiver and regular renewal (every 4 minutes). Here is the code:

using Azure.Messaging.ServiceBus;

internal interface IAnotherVideoFileProcessor : IAsyncDisposable
{
    Task StartProcessingAsync(CancellationToken cancellationToken);
    Task StopProcessingAsync(CancellationToken cancellationToken);
}

internal class AnotherVideoFileProcessor : IAnotherVideoFileProcessor
{
    private readonly MessageSource _messageSource;
    private readonly ISystemLogger _logger;
    private readonly ServiceBusClient _client;
    private readonly ServiceBusProcessor _processor;

    public AnotherVideoFileProcessor(
        ISystemLogger logger,
        MessageSource messageSource)
    {
        _logger = logger;
        _messageSource = messageSource;
        _client = new ServiceBusClient(_messageSource.ConnectionString);
        var options = new ServiceBusProcessorOptions
        {
            AutoCompleteMessages = false,

            MaxConcurrentCalls = 1,
            MaxAutoLockRenewalDuration = TimeSpan.FromMinutes(120),
        };
        _processor = _client.CreateProcessor(_messageSource.EntityName, _messageSource.SubscriptionName, options);
    }

    public async ValueTask DisposeAsync()
    {
        await _processor.DisposeAsync();
        await _client.DisposeAsync();
    }

    public async Task StartProcessingAsync(CancellationToken cancellationToken)
    {
        async Task MessageHandler(ProcessMessageEventArgs args)
        {
            try
            {
                string body = args.Message.Body.ToString();
                _logger.Info($"New message received ({args.Message.MessageId}): {body}");

                await Task.Delay(TimeSpan.FromMinutes(27), cancellationToken);

                _logger.Info($"Completing {args.Message.MessageId}");
                await args.CompleteMessageAsync(args.Message, cancellationToken);
            }
            catch (Exception ex)
            {
                _logger.LogException(ex);
            }
        }

        Task ErrorHandler(ProcessErrorEventArgs args)
        {
            _logger.LogException(args.Exception);
            return Task.CompletedTask;
        }

        _processor.ProcessMessageAsync += MessageHandler;
        _processor.ProcessErrorAsync += ErrorHandler;

        _logger.Debug($"{nameof(AnotherVideoFileProcessor)}: Start processing.");
        await _processor.StartProcessingAsync(cancellationToken);
    }

    public async Task StopProcessingAsync(CancellationToken cancellationToken)
    {
        _logger.Debug($"{nameof(AnotherVideoFileProcessor)}: Stopping processing...");
        await _processor.StopProcessingAsync(cancellationToken);
        _logger.Debug($"{nameof(AnotherVideoFileProcessor)}: Stopped.");
    }
}

Actual Behavior

Logs:

26 Nov 2023 23:44:00.853: New message received (e217c3c1cc1648519dfdbc288c14a46b):
27 Nov 2023 00:11:00.861: Completing e217c3c1cc1648519dfdbc288c14a46b
27 Nov 2023 00:11:00.890: The lock supplied is invalid. Either the lock expired, or the message has already been removed from the queue, or was received by a different receiver instance. (MessageLockLost). For troubleshooting information, see https://aka.ms/azsdk/net/servicebus/exceptions/troubleshoot.

Expected Behavior

Message should be completed successfully.

[jsquire]

@EldertGrootenboer: Based on the discussion, here and Stack Overflow, it appears that the client is renewing the lock correctly, but the service is rejecting the settlement if renewal is performed for more than 17 minutes. This can also be reproduced when using the receiver and manually calling to renew the lock.

I believe this requires service investigation, as it does not appear to be under the control of the client.

[jsquire]

From @SeanFeldman on the original issue:

I've tried to reproduce this and can confirm that the message lock is renewed for over 20 minutes (I tried with 25), but when the message settlement is attempted to complete the message using ProcessMessageEventArgs, the operation fails.

[EldertGrootenboer]

Thank you for your feedback. We have opened an investigation task for this in our backlog, and will update this issue when we have more information.

[volkonst]

We are facing similar issue, but only when the MessageHandler causes a heavy CPU load. In this case the message lock is not being renewed and attempt to call CompleteMessageAsync after the message processing is done results in the "The lock supplied is invalid" exception. Hope it can help with the investigation.

[EldertGrootenboer]

This item in our backlog, however we currently don't have an ETA on when development might start on this. For now, to help us give this the right priority, it would be helpful to see others vote and support this item.