Azure / Azure/azure-functions-dotnet-worker
Azure.Messaging.ServiceBus: The lock supplied is invalid when function throws exception
- Dominant language
- C#
- Stars
- 466
- Forks
- 215
- Avg merge
- 3d 10h
- Merged PRs (30d)
- 7
Description
Hello,
It seems that if a Service Bus trigger function throws an exception, even after the function has finished executing, I'm seeing a `Azure.Messaging.ServiceBus: The lock supplied is invalid` exception in the console.
Any reasons why the function attempts to renew the lock token after it failed executing? This adds noise to our Application Insights logs.
```
[2022-08-23T12:34:03.472Z] Worker process started and initialized.
[2022-08-23T12:34:38.603Z] Executing 'Functions.MyFunctionFunction' (Reason='(null)', Id=6ebb7300-380c-461d-9429-85ef76066dce)
[2022-08-23T12:34:38.605Z] Trigger Details: MessageId: 5e4e10d7bbbf418f8170c0261f208e42, SequenceNumber: 13, DeliveryCount: 1, EnqueuedTimeUtc: 2022-08-23T12:34:38.3280000+00:00, LockedUntilUtc: 2022-08-23T12:35:08.3440000+00:00, SessionId: (null)
[2022-08-23T12:34:38.800Z] Configured endpoint MyFunction, Consumer: MyCompany.MyAppIntegration.MyFunction.Function.MassTransitConsumers.MyFunctionConsumer
[2022-08-23T12:34:39.793Z] Executed 'Functions.MyFunctionFunction' (Failed, Id=6ebb7300-380c-461d-9429-85ef76066dce, Duration=1214ms)
[2022-08-23T12:34:39.794Z] System.Private.CoreLib: Exception while executing function: Functions.MyFunctionFunction. System.Private.CoreLib: Result: Failure
Exception: System.AggregateException: One or more errors occurred. (The method or operation is not implemented.)
[2022-08-23T12:34:39.795Z] ---> System.NotImplementedException: The method or operation is not implemented.
[2022-08-23T12:34:39.796Z] at MyCompany.MyAppIntegration.MyFunction.Function.MyFunctionFunction.Run(Byte[] message, FunctionContext context) in C:\Repos\MyCompany\MyApp\src\MyCompany.MyAppIntegration.MyFunction.Function\MyFunctionFunction.cs:line 21
[2022-08-23T12:34:39.798Z] at Microsoft.Azure.Functions.Worker.Invocation.VoidTaskMethodInvoker`2.InvokeAsync(TReflected instance, Object[] arguments) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\VoidTaskMethodInvoker.cs:line 22
[2022-08-23T12:34:39.799Z] --- End of inner exception stack trace ---
[2022-08-23T12:34:39.801Z] at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
[2022-08-23T12:34:39.802Z] at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
[2022-08-23T12:34:39.807Z] at System.Threading.Tasks.Task`1.get_Result()
[2022-08-23T12:34:39.809Z] at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionInvoker`2.<>c.b__6_0(Task`1 t) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionInvoker.cs:line 32
[2022-08-23T12:34:39.810Z] at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
[2022-08-23T12:34:39.812Z] at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
[2022-08-23T12:34:39.813Z] --- End of stack trace from previous location ---
[2022-08-23T12:34:39.814Z] at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
[2022-08-23T12:34:39.816Z] --- End of stack trace from previous location ---
[2022-08-23T12:34:39.817Z] at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionExecutor.ExecuteAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionExecutor.cs:line 44
[2022-08-23T12:34:39.823Z] at Microsoft.Azure.Functions.Worker.OutputBindings.OutputBindingsMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in D:\a\_work\1\s\src\DotNetWorker.Core\OutputBindings\OutputBindingsMiddleware.cs:line 13
[2022-08-23T12:34:39.824Z] at Microsoft.Azure.Functions.Worker.GrpcWorker.InvocationRequestHandlerAsync(InvocationRequest request, IFunctionsApplication application, IInvocationFeaturesFactory invocationFeaturesFactory, ObjectSerializer serializer, IOutputBindingsInfoProvider outputBindingsInfoProvider, IInputConversionFeatureProvider functionInputConversionFeatureProvider) in D:\a\_work\1\s\src\DotNetWorker.Grpc\GrpcWorker.cs:line 199
Stack: at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
[2022-08-23T12:34:39.827Z] at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
[2022-08-23T12:34:39.828Z] at System.Threading.Tasks.Task`1.get_Result()
[2022-08-23T12:34:39.830Z] at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionInvoker`2.<>c.b__6_0(Task`1 t) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionInvoker.cs:line 32
[2022-08-23T12:34:39.832Z] at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
[2022-08-23T12:34:39.833Z] at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
[2022-08-23T12:34:39.839Z] --- End of stack trace from previous location ---
[2022-08-23T12:34:39.840Z] at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
[2022-08-23T12:34:39.842Z] --- End of stack trace from previous location ---
[2022-08-23T12:34:39.844Z] at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionExecutor.ExecuteAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionExecutor.cs:line 44
[2022-08-23T12:34:39.845Z] at Microsoft.Azure.Functions.Worker.OutputBindings.OutputBindingsMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in D:\a\_work\1\s\src\DotNetWorker.Core\OutputBindings\OutputBindingsMiddleware.cs:line 13
[2022-08-23T12:34:39.847Z] at Microsoft.Azure.Functions.Worker.GrpcWorker.InvocationRequestHandlerAsync(InvocationRequest request, IFunctionsApplication application, IInvocationFeaturesFactory invocationFeaturesFactory, ObjectSerializer serializer, IOutputBindingsInfoProvider outputBindingsInfoProvider, IInputConversionFeatureProvider functionInputConversionFeatureProvider) in D:\a\_work\1\s\src\DotNetWorker.Grpc\GrpcWorker.cs:line 199.
[2022-08-23T12:34:39.913Z] Message processing error (Action=ProcessMessageCallback, EntityPath=test-cosmin, Endpoint=myapp-dev-sbn.servicebus.windows.net)
[2022-08-23T12:34:39.917Z] System.Private.CoreLib: Exception while executing function: Functions.MyFunctionFunction. System.Private.CoreLib: Result: Failure
Exception: System.AggregateException: One or more errors occurred. (The method or operation is not implemented.)
[2022-08-23T12:34:39.919Z] ---> System.NotImplementedException: The method or operation is not implemented.
[2022-08-23T12:34:39.923Z] at MyCompany.MyAppIntegration.MyFunction.Function.MyFunctionFunction.Run(Byte[] message, FunctionContext context) in C:\Repos\MyCompany\MyApp\src\MyCompany.MyAppIntegration.MyFunction.Function\MyFunctionFunction.cs:line 21
[2022-08-23T12:34:39.926Z] at Microsoft.Azure.Functions.Worker.Invocation.VoidTaskMethodInvoker`2.InvokeAsync(TReflected instance, Object[] arguments) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\VoidTaskMethodInvoker.cs:line 22
[2022-08-23T12:34:39.928Z] --- End of inner exception stack trace ---
[2022-08-23T12:34:39.933Z] at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
[2022-08-23T12:34:39.939Z] at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
[2022-08-23T12:34:39.941Z] at System.Threading.Tasks.Task`1.get_Result()
[2022-08-23T12:34:39.943Z] at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionInvoker`2.<>c.b__6_0(Task`1 t) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionInvoker.cs:line 32
[2022-08-23T12:34:39.946Z] at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
[2022-08-23T12:34:39.947Z] at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
[2022-08-23T12:34:39.949Z] --- End of stack trace from previous location ---
[2022-08-23T12:34:39.954Z] at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
[2022-08-23T12:34:39.956Z] --- End of stack trace from previous location ---
[2022-08-23T12:34:39.958Z] at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionExecutor.ExecuteAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionExecutor.cs:line 44
[2022-08-23T12:34:39.960Z] at Microsoft.Azure.Functions.Worker.OutputBindings.OutputBindingsMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in D:\a\_work\1\s\src\DotNetWorker.Core\OutputBindings\OutputBindingsMiddleware.cs:line 13
[2022-08-23T12:34:39.962Z] at Microsoft.Azure.Functions.Worker.GrpcWorker.InvocationRequestHandlerAsync(InvocationRequest request, IFunctionsApplication application, IInvocationFeaturesFactory invocationFeaturesFactory, ObjectSerializer serializer, IOutputBindingsInfoProvider outputBindingsInfoProvider, IInputConversionFeatureProvider functionInputConversionFeatureProvider) in D:\a\_work\1\s\src\DotNetWorker.Grpc\GrpcWorker.cs:line 199
Stack: at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
[2022-08-23T12:34:39.965Z] at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
[2022-08-23T12:34:39.971Z] at System.Threading.Tasks.Task`1.get_Result()
[2022-08-23T12:34:39.972Z] at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionInvoker`2.<>c.b__6_0(Task`1 t) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionInvoker.cs:line 32
[2022-08-23T12:34:39.974Z] at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
[2022-08-23T12:34:39.976Z] at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
[2022-08-23T12:34:39.978Z] --- End of stack trace from previous location ---
[2022-08-23T12:34:39.979Z] at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
[2022-08-23T12:34:39.980Z] --- End of stack trace from previous location ---
[2022-08-23T12:34:39.986Z] at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionExecutor.ExecuteAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionExecutor.cs:line 44
[2022-08-23T12:34:39.988Z] at Microsoft.Azure.Functions.Worker.OutputBindings.OutputBindingsMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in D:\a\_work\1\s\src\DotNetWorker.Core\OutputBindings\OutputBindingsMiddleware.cs:line 13
[2022-08-23T12:34:39.992Z] at Microsoft.Azure.Functions.Worker.GrpcWorker.InvocationRequestHandlerAsync(InvocationRequest request, IFunctionsApplication application, IInvocationFeaturesFactory invocationFeaturesFactory, ObjectSerializer serializer, IOutputBindingsInfoProvider outputBindingsInfoProvider, IInputConversionFeatureProvider functionInputConversionFeatureProvider) in D:\a\_work\1\s\src\DotNetWorker.Grpc\GrpcWorker.cs:line 199.
[2022-08-23T12:34:59.014Z] Message processing error (Action=RenewLock, EntityPath=test-cosmin, Endpoint=myapp-dev-sbn.servicebus.windows.net)
[2022-08-23T12:34:59.017Z] Azure.Messaging.ServiceBus: The lock supplied is invalid. Either the lock expired, or the message has already been removed from the queue. For more information please see https://aka.ms/ServiceBusExceptions . Reference:171c39c8-917c-4c3b-b435-5e7460e2a38a, TrackingId:7917be18-7e2f-4eaf-907c-4f46f487adb9_B23, SystemTracker:myapp-dev-sbn:Queue:test-cosmin, Timestamp:2022-08-23T12:34:58 (MessageLockLost).
```
As you can see in the logs above `Azure.Messaging.ServiceBus: The lock supplied is invalid` is logged 20 seconds after the last log message, this is rather unexpected as I don't understand why the runtime attempts to renew the lock of a failed execution which lead to a dead-lettered message.
Contributor guide
No contributing guide indexed for this repository
Research direction
Start with the Service Bus trigger scenario and the invocation entry points named in the log: Function.Run, DefaultFunctionInvoker, DefaultFunctionExecutor, and GrpcWorker. Reproduce a failed function and inspect the RenewLock path associated with the 20-second delayed error. Done means a failed invocation no longer produces an unexpected lock-renewal error, with coverage for the reported behavior.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- azure, csharp
- Domain
- backend, cloud
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 30/100