Azure Function v3 .NET Core 3.1 ServiceBusTrigger "Message processing error (Action=RenewLock)" even though autoComplete = false

Question

I have a queue trigger that runs a long running task. Ran into all sorts of problems with lock durations and renewal, so I decided to manually complete the message at the very start of the whole process. If the job encounters an error, send the message back to the queue.

In the Log Data below, you can see it gets the message, completes it, starts the task, logs a lock supplied is invalid error which seems to affect nothing, then completes the task. I want to stop this error. It's annoying.

[FunctionName("QueueTrigger")]
public async Task RunQueue([ServiceBusTrigger("queuename", Connection = "cn")] Message message, MessageReceiver messageReceiver, [ServiceBus("queuename", Connection = "cn")] IAsyncCollector<Message> queue)
{
    var msg = JsonConvert.DeserializeObject<RequestObj>(Encoding.UTF8.GetString(message.Body));
    logger.LogInfo("*** Before complete");
    await messageReceiver.CompleteAsync(message.SystemProperties.LockToken);
    logger.LogInfo("*** After complete");
    try
    {
        if(msg.Whatever > 1)   throw new Exception("Bogus exception thrown for testing.");

        var result = await RunTheTask(msg);
        if (!result.IsSuccessful)
        {
            logger.LogError(result.Failure);
            throw new ApplicationException(result.Failure);
        };
    }
    catch (Exception ex)
    {
        logger.LogError(ex.Message);
        logger.LogInfo("*** About to requeue");
        await queue.AddAsync(new Message(message.Body));
        logger.LogSuccess("*** Queued the message again.");
    }
}

host.json file has serviceBus config like so (turning autoComplete off)

"serviceBus": {
      "prefetchCount": 1,
      "messageHandlerOptions": {
        "autoComplete": false,
        "maxConcurrentCalls": 1
      },
      "SessionHandlerOptions": {
        "autoComplete": false
      },
      "BatchOptions": {
        "AutoComplete": false
      }

In both cases, the code works as expected, but again in both cases I always see an "invalid lock" error

Some log stuff:

[2021-02-01T20:46:27.248Z] Executing 'QueueTrigger' (Reason='(null)', Id=520a670c-e636-49b8-96b5-7502f6b479ac)
[2021-02-01T20:46:27.251Z] Trigger Details: MessageId: d7af56ed083947e99ce0fc468f111e4d, SequenceNumber: 37, DeliveryCount: 1, EnqueuedTimeUtc: 2021-02-01T20:40:44.5390000Z, LockedUntilUtc: 2021-02-01T20:41:44.5550000Z, SessionId: (null)
[2021-02-01T20:46:28.331Z] *** Before complete
[2021-02-01T20:46:28.471Z] *** After complete
[2021-02-01T20:46:28.498Z] Running the Task
[2021-02-01T20:46:28.826Z] Message processing error (Action=RenewLock, ClientId=whatever, EntityPath=queueName, Endpoint=blah.servicebus.windows.net)
[2021-02-01T20:46:28.830Z] Microsoft.Azure.ServiceBus: The lock supplied is invalid. Either the lock expired, or the message has already been removed from the queue. Reference:30780d70-2887-4923-8725-329ab94dd4b2, TrackingId:e3e85f42-1c62-44da-b858-1c856f972a1f_B14, SystemTracker:x:Queue:queueName, Timestamp:2021-02-01T20:40:46.
[2021-02-01T20:46:38.855Z] Finished the Task
[2021-02-01T20:46:42.221Z] Executed 'QueueTrigger' (Succeeded, Id=520a670c-e636-49b8-96b5-7502f6b479ac, Duration=14992ms)

Answer 1

I think you should move the 'complete' method to the end, the function will automatically refresh the lock expiration time to keep it available under normal circumstances. But once you use the 'complete' method, the function will generate the last lock, and if your subsequent logic exceeds the lock time, a lock expiration exception will be thrown. You can look at the following code and compare using complete and not using complete The difference:

using System;
using System.Text;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Azure.ServiceBus;
using Microsoft.Azure.ServiceBus.Core;
using Microsoft.Azure.WebJobs;
using Microsoft.Azure.WebJobs.Host;
using Microsoft.Extensions.Logging;
using Newtonsoft.Json;

namespace FunctionApp71
{
    public static class Function1
    {
        [FunctionName("Function1")]
        public static async Task Run([ServiceBusTrigger("queuename", Connection = "cn")] Message message, MessageReceiver messageReceiver, [ServiceBus("queuename", Connection = "cn")] IAsyncCollector<Message> queue, ILogger logger)
        {
            logger.LogInformation("When the message comes in, the expire time is: "+message.SystemProperties.LockedUntilUtc.ToString());//Now the time is 2/4/2021 8:29:00 AM

            Thread.Sleep(6000);

            logger.LogInformation("After 6 seconds, the expired time is :"+message.SystemProperties.LockedUntilUtc.ToString());//The time of the lock is renewed, so now the time is 2/4/2021 8:29:04 AM

            //When you complete the message, there is no way to renew the lock because the lock is not exist(Azure function stop renew the lock.).
            await messageReceiver.CompleteAsync(message.SystemProperties.LockToken);
            logger.LogInformation("After complete the message, the expired time is :"+message.SystemProperties.LockedUntilUtc.ToString());//Now the time is still 2/4/2021 8:29:04 AM

            Thread.Sleep(6 * 1000);//Your try catch is here.

            logger.LogInformation("After complete message and 6 seconds later, the expired time is :"+message.SystemProperties.LockedUntilUtc.ToString());
        }
    }
}

Answer 2

Logged an issue: https://github.com/Azure/azure-functions-servicebus-extension/issues/137 Issue has a link to a repo to repro.