Azure Service Bus keeps throwing MessageLockLostExceptions

3
votes

I keep getting MessageLockLostExceptions when processing messages.

Now I want to simulate a slightly longer running message processing task (but still well within LockDuration) by adding Task.Delay(10_000). But then I get a MessageLockLostException for exactly every 4th message.

This happens even if I set MaxAutoRenewDuration = TimeSpan.FromDays(30) and PrefetchCount = 0.

This is the message processing method, which I changed slightly to print out the remaining lock duration:

    private static async Task processMessagesAsync(Message message, CancellationToken token)
    {
        Console.Write($"Received message: {message.SystemProperties.SequenceNumber}. Remaining lock duration: {message.SystemProperties.LockedUntilUtc - DateTime.UtcNow}");
        await Task.Delay(10000);
        await queueClient.CompleteAsync(message.SystemProperties.LockToken);
        Console.WriteLine(" - Complete!");
    }

Sample output:

======================================================
Press ENTER key to exit after receiving all the messages.
======================================================
Received message: 3659174697238584. Remaining lock duration: 00:00:30.8269132 - Complete!
Received message: 19421773393035331. Remaining lock duration: 00:00:20.5271654 - Complete!
Received message: 11540474045136941. Remaining lock duration: 00:00:10.3372697 - Complete!
Received message: 15762598695796784. Remaining lock duration: 00:00:00.1776760
Message handler encountered an exception     Microsoft.Azure.ServiceBus.MessageLockLostException: The lock supplied is invalid. Either the lock expired, or the message has already been removed from the queue. Reference:2c6caac3-e607-4130-a522-f75e4636e130, TrackingId:3ff82738-664d-4aca-b55f-ba3900f1c640_B17, SystemTracker:ocgtesting:queue:workflow~63, Timestamp:2018-12-12T17:01:59
at Microsoft.Azure.ServiceBus.Core.MessageReceiver.OnRenewLockAsync(String lockToken) in C:\source\azure-service-bus-dotnet\src\Microsoft.Azure.ServiceBus\Core\MessageReceiver.cs:line 1260
at Microsoft.Azure.ServiceBus.Core.MessageReceiver.<>c__DisplayClass74_0.<<RenewLockAsync>b__0>d.MoveNext() in C:\source\azure-service-bus-dotnet\src\Microsoft.Azure.ServiceBus\Core\MessageReceiver.cs:line 771
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.ServiceBus.RetryPolicy.RunOperation(Func`1 operation, TimeSpan operationTimeout) in C:\source\azure-service-bus-dotnet\src\Microsoft.Azure.ServiceBus\RetryPolicy.cs:line 83
at Microsoft.Azure.ServiceBus.RetryPolicy.RunOperation(Func`1 operation, TimeSpan operationTimeout) in C:\source\azure-service-bus-dotnet\src\Microsoft.Azure.ServiceBus\RetryPolicy.cs:line 105
at Microsoft.Azure.ServiceBus.Core.MessageReceiver.RenewLockAsync(String lockToken) in C:\source\azure-service-bus-dotnet\src\Microsoft.Azure.ServiceBus\Core\MessageReceiver.cs:line 773
at Microsoft.Azure.ServiceBus.Core.MessageReceiver.RenewLockAsync(Message message) in C:\source\azure-service-bus-dotnet\src\Microsoft.Azure.ServiceBus\Core\MessageReceiver.cs:line 742
at Microsoft.Azure.ServiceBus.MessageReceivePump.RenewMessageLockTask(Message message, CancellationToken renewLockCancellationToken) in C:\source\azure-service-bus-dotnet\src\Microsoft.Azure.ServiceBus\MessageReceivePump.cs:line 248.

Full code here: https://pastebin.com/sFGBgE0s

2
c#azureservicebusazure-servicebus-queues
How do you receive your messages? Can you share a full repro? The fact that you receive messages with remaining lock duration less than MaxLockDuration is a clear indication something is off. – Sean Feldman
@SeanFeldman Yes, here: pastebin.com/sFGBgE0s – Mo B.
The code in pastebin uses Thread.Sleep instead of TaskDelay, and PrefetchCount=0 has been commented out, but that didn't make a difference. – Mo B.
What version of the ASB client are you using? – Sean Feldman
I suspect this is a bug. See my answer below. – Sean Feldman

2 Answers

3
votes

One thing that is missing from your repro is the queue description. It's important to note such details as the problem you're experiencing has nothing to do with the client and is most likely either related to the broker or the underlying AMQP library.

For non-partitioned queues this setup works fine. It doesn't for partitioned queues (Standard tier). Can be observed with both the old and the new clients. I've raised a broker related issue for Azure Service Bus team to investigate.

1
votes

You need to Complete the message before the Lock Token gets expired. Once the Lock Token is expired, you will receive MessageLockLostException during the complete operation.

I can see that you are delaying the thread execution by 10 seconds for each message. But the messages seems to be fetched at the same point of time, that's why the remaining lock duration keeps reducing for each message.

For the fourth message, the Remaining lock duration is 00:00:00.1776760. So, after 177 milliseconds, the lock will expire. You are delaying the thread by 10 seconds in the next line. So, the lock would expire and you are getting MessageLockLostException. To avoid this exception, remove the Delay