4

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

Mo B.
  • 5,307
  • 3
  • 25
  • 42
  • 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 Dec 12 '18 at 18:22
  • @SeanFeldman Yes, here: https://pastebin.com/sFGBgE0s – Mo B. Dec 13 '18 at 12:00
  • 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. Dec 13 '18 at 12:05
  • What version of the ASB client are you using? – Sean Feldman Dec 13 '18 at 15:17
  • I've ran it against the latest version of the client with [10 messages](https://imgur.com/a/YvPibYz) in queue and all worked well. Wouldn't recommend using Thread.Delay, rather Task.Delay, but that doesn't seem to be the issue here. – Sean Feldman Dec 13 '18 at 19:32
  • I am using Microsoft.Azure.ServiceBus 3.2.0 with .NET Core 2.1. I am still getting this weird pattern of decreasing remaining lock duration. – Mo B. Dec 14 '18 at 10:18
  • Sean, which version did you use? – Mo B. Dec 14 '18 at 11:50
  • I got a bit closer to the cause of the problem: if I reduce the delay to 200ms and print out LockedUntilUtc, I see that the messages are prefetched in batches of 16. (16 consecutive messages have the same LockedUntilUtc.) So how to disable prefetching? – Mo B. Dec 14 '18 at 13:00
  • Latest 3.2.0 with .NET Framework. This is why code should be shared as a repo and not a snippet . Anyhow, I have a hunch what it could be, will need to check and share. – Sean Feldman Dec 14 '18 at 17:11
  • I've checked and the following is what's happening: `QueueClient` has a `MessageReceiver`. When a `MessageHandler` is registered, a `MessageReceivePump` is created, using the same receiver of the queue client. If prefetch is set to zero, that will be the same prefetch. This should work unless there's some sort of bug you've ran into. Mind to share a GitHub repor with your finding? I want to see all details, packages, etc. Thanks. – Sean Feldman Dec 14 '18 at 21:33
  • Updated to 3.2.1, but the error is still there. Here is the repo: https://github.com/mywyb2/ServiceBusTest Thank you! – Mo B. Dec 15 '18 at 08:57
  • 1
    I suspect this is a bug. See my answer [below](https://stackoverflow.com/a/53796713/59563). – Sean Feldman Dec 15 '18 at 19:54

2 Answers2

4

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.

Sean Feldman
  • 23,443
  • 7
  • 55
  • 80
1

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

Arunprabhu
  • 1,454
  • 9
  • 15
  • I added the delay deliberately to simulate a task that runs a bit longer - but less long as the LockDuration. The question is why the remaining lock duration keeps decreasing. – Mo B. Dec 13 '18 at 11:56
  • Messages will be continuously received by processMessagesAsync. Say if you have 10 messages, all the messages will be received one by one despite of what you have inside processMessagesAsync. Hence 10 messages will be queued for the Delay, resulting in lock token expiry. Kindly note: The message retrieval will not wait for processMessagesAsync to complete execution, messages will piled up for the Delay. – Arunprabhu Dec 13 '18 at 13:01
  • 1
    The observed behaviour indeed matches your explanation. But this would be a bug, wouldn't it? I have set PrefetchCount = 0, which should disable prefetching (see https://learn.microsoft.com/en-us/azure/service-bus-messaging/service-bus-prefetch). There must be a way to disable prefetching, otherwise it would be impossible to avoid lock expiry. – Mo B. Dec 13 '18 at 14:46
  • This is not a bug. It is the expected behavior. Prefetch only fetches the messages in background and make it available for the receiver for faster processing with a help of temporary memory. In your case, if you use RegisterMessageHandler(), it will not work like a While loop, it fetches the message and initiate the ProcessMessageAsync() asynchronously. If you want the next message to be received only after the completion of your task, you should use ReceiveAsync() inside a while loop. – Arunprabhu Dec 14 '18 at 05:58
  • Then what does the QueueClient.Prefetch property do? I thought that setting Prefetch=0 would disable prefetching, so the next message will only be loaded into the buffer after the previous message has been completed. – Mo B. Dec 14 '18 at 10:08
  • Prefetch loads the messages in background in a buffer and provides it in a faster rate for the client. The purpose of perfetch it to improve the speed of message processing. – Arunprabhu Dec 14 '18 at 11:14
  • Just a comment, API wise, if Prefetch is set to zero and MessageHandlerOptions concurrency level is set to 1, this is inadvertently same as `ReceiveAsync()`. Will dig into this a bit more to have more than just this comment. – Sean Feldman Dec 14 '18 at 17:09
  • 2
    @Arunprabhu prefetch on message receiver is zero by default. MoB is explicitly setting it to zero. His setup is valid and if he wants to do serial processing using message handler API for simplicity, that's absolutely fine. I suspect this is a bug. See my answer. – Sean Feldman Dec 15 '18 at 19:53
  • @SeanFeldman I understand it now.Thanks for the clarification :) – Arunprabhu Dec 17 '18 at 04:51