Renewal of messages is executed even if the message has been completed

[havarnov]

This might not be a bug, but misuse of the library.

Actual Behavior

1. Setup message handler (QueueClient.RegisterMessageHandler)
2. Complete the message as soon as it comes in
3. Delay the message handler after completion for a longer time span than the LockDuration
4. ExceptionReceivedHandler will receive a "Microsoft.Azure.ServiceBus.MessageLockLostException" because the library tries to renew an already completed message

Expected Behavior

1. Setup message handler (QueueClient.RegisterMessageHandler)
2. Complete the message as soon as it comes in
3. Delay the message handler after completion for a longer time span than the LockDuration
4. ExceptionReceivedHandler will not receive any exception as the RenewMessageTask should've been canceled.

using System;
using System.Text;
using System.Threading.Tasks;

using Microsoft.Azure.ServiceBus;
using Microsoft.Azure.ServiceBus.Management;

namespace service_bus_renew_bug
{
    class Program
    {
        static void Main(string[] args)
        {
            MainAsync(args).GetAwaiter().GetResult();
        }

        static async Task MainAsync(string[] args)
        {
            var mgmtClient = new ManagementClient(args[0]);
            if (!await mgmtClient.QueueExistsAsync(args[1]))
            {
                await mgmtClient.CreateQueueAsync(args[1]);
            }

            var queueClient = new QueueClient(args[0], args[1]);

            queueClient.RegisterMessageHandler(
                async (msg, token) =>
                {
                    if (token.IsCancellationRequested)
                    {
                        return;
                    }

                    await queueClient.CompleteAsync(msg.SystemProperties.LockToken);
                    Console.WriteLine(Encoding.UTF8.GetString(msg.Body));
                    // default LockDuration == TimeSpan.FromMinutes(1)
                    await Task.Delay(TimeSpan.FromMinutes(1.5));
                },
                new MessageHandlerOptions((e) =>
                {
                    Console.WriteLine(e.Exception.GetType());
                    Console.WriteLine(e.Exception.Message);
                    return Task.CompletedTask;
                })
                {
                    AutoComplete = false,
                    MaxConcurrentCalls = 1,
                    MaxAutoRenewDuration = TimeSpan.FromMinutes(2),
                });

            await queueClient.SendAsync(new Message(Encoding.UTF8.GetBytes("foobar")));

            Console.Write("[Enter] to stop.");
            Console.ReadLine();
        }
    }
}

Versions

• OS platform and version: Any
• .NET Version: .Net Core 2.1
• NuGet package version or commit ID: "Microsoft.Azure.ServiceBus" Version="3.1.1"

[havarnov]

If not a bug, at least it can be useful to make the information about this behavior available for others.

[Kadajski]

I have run into this same issue. Looking at the source it seems like renew is a task that gets queued before the message comes in and only gets cancelled when the func has completely ended.

Whats the solution to an issue like this? Or is this a bug? How do you "ack" a message with Azure ServiceBus using thisMessageReceiver class.

[SeanFeldman]

Looking at the repro steps, it says:

Complete the message as soon as it comes in
Delay the message handler after completion for a longer time span than the LockDuration

At the same time, there's an explicit message auto-renewal.

MaxAutoRenewDuration = TimeSpan.FromMinutes(2)

Aren't those conflicting? Why would one complete the message, halt the callback, and have auto-renewal set -up? I'd expect to see auto-renewal used when auto-forwarding is used. Ti ensure that a long running processing callack has enough time to complete. Feels like API misunderstanding/misuse.

[SeanFeldman]

@havarnov does my comment above clarifies not a bit more?

[Kadajski]

@SeanFeldman that may be correct in this scenario. Though the default for the auto-renew is on and makes sense to be on. This feels like a bug to me anyways just because it's over-complicating what should be a simple API.

Another scenario in which this definitely feels broken is If you do pre-fetch, and set auto-complete to false. You then want the renew to be there to ensure that the pre-fetched messages get renewed to avoid any issues, while you still want to complete it yourself to mark it as "acknowledged". In this scenario when you complete it you would want the renew to stop renewing inside of the func to avoid these errors.

Example code:

public class ServiceBusTester
{
    private readonly string _connectionString;
    private readonly string _queue;

    public ServiceBusTester(string connectionString, string queue)
    {
        _connectionString = connectionString;
        _queue = queue;
    }

    public void Receive()
    {
        var receiver = new MessageReceiver(_connectionString, _queue)
        {
            PrefetchCount = 100
        };
        receiver.RegisterMessageHandler(async (message, token) =>
        {
            // Do some initial processing
            Console.WriteLine($"Incoming message. Size: {message.Body.Length}");

            // Acknowledge message is done
            await receiver.CompleteAsync(message.SystemProperties.LockToken);

            // Additional non-important work is done that takes a long time
            // Queue renew duration is set to default(30s)
            await Task.Delay(50_000);
                                
            Console.WriteLine($"Message Processing completed");
        },
        new MessageHandlerOptions(e =>
        {
            // Throws
            // "The lock supplied is invalid. Either the lock expired, or the message has already been removed from the queue."
            Console.WriteLine(e);
            return Task.CompletedTask;
        })
        {
            // The default value for this is to renew. so no need to set it
            // MaxAutoRenewDuration
            AutoComplete = false
        });
    }

    public async Task SendMessage()
    {
        var sender = new MessageSender(_connectionString, _queue);
        await sender.SendAsync(new Message(Encoding.UTF8.GetBytes("Hello world")));
    }
}

[havarnov]

@SeanFeldman that's why I said that this might not be a bug. Alltough @Kadajski example is more 'realistic' I guess.

I think this should be fixed as I don't think this will have any negative effects. I'm happy to provide a PR as soon as I get time for it.

[SeanFeldman]

@Kadajski @havarnov PreFetch needs to be adjusted based on the time it takes to process a message in the user callback. There's no point of prefetching a large number of messages, knowing that your callback is taking long time to process a single message. Lock auto-renewal will not kick in until message is given to the callback. Meaning that some messages will lose their lock token even prior to be processed. Either concurrency of the callback via MessageHandlerOption needs to be configured to a higher number or the PrefetchCount on the receiver needs to be reduced.