ServiceBusProcessor loses lock if processing is going longer than 20 minutes

[ygavrishov]

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.

[SeanFeldman]

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.

[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. This can also be reproduced when using the receiver and manually calling to renew the lock.

As this requires service investigation, I'm going to transfer this back over to the Service Bus repository.

[jsquire]

This has been transferred to the Azure Service Bus repository as #685 for service team investigation.