Extensions RPC lifetime mismatch between server and JobHost leads to incorrect RPC calls

[jviau]

The current design of the extension RPC server has it piggy backing off the general worker gRPC server. The lifetime mismatch between individual workers and this server causes issues during job host transitions. We will need explore one of two options:

1. Improve lifetime tracking with the existing RPC server
   • Only unregister endpoints when functions have finished draining.
   • Support multiple job hosts being registered. Will need to include an identifier for what set of endpoints an extension call needs to be routed to.
2. OR move these endpoints into a new server that lives in the job host.
   • Will need to measure the impact an extra server startup will have.

[goldmelodyvn]

Vote up. We have a lot of RPC exception when send a bulk of messages to Azure message bus.
When we did manual testing ( a few message we don't have this issue). When we did Load test with around 6000 messages. We got 9.50k Rpc exception as below:

Exception while executing function: Functions.[xxx] Result: Failure
Exception: System.IO.FileNotFoundException: Could not load file or assembly 'Microsoft.Azure.Functions.Worker.Extensions.Abstractions, Version=1.3.0.0, Culture=neutral, PublicKeyToken=551316b6919f366c'. The system cannot find the file specified.
File name: 'Microsoft.Azure.Functions.Worker.Extensions.Abstractions, Version=1.3.0.0, Culture=neutral, PublicKeyToken=551316b6919f366c'
   at System.ModuleHandle.ResolveType(QCallModule module, Int32 typeToken, IntPtr* typeInstArgs, Int32 typeInstCount, IntPtr* methodInstArgs, Int32 methodInstCount, ObjectHandleOnStack type)
   at System.ModuleHandle.ResolveTypeHandle(Int32 typeToken, RuntimeTypeHandle[] typeInstantiationContext, RuntimeTypeHandle[] methodInstantiationContext)
   at System.Reflection.RuntimeModule.ResolveType(Int32 metadataToken, Type[] genericTypeArguments, Type[] genericMethodArguments)
   at System.Reflection.CustomAttribute.FilterCustomAttributeRecord(MetadataToken caCtorToken, MetadataImport& scope, RuntimeModule decoratedModule, MetadataToken decoratedToken, RuntimeType attributeFilterType, Boolean mustBeInheritable, ListBuilder`1& derivedAttributes, RuntimeType& attributeType, IRuntimeMethodInfo& ctorWithParameters, Boolean& isVarArg)
   at System.Reflection.CustomAttribute.AddCustomAttributes(ListBuilder`1& attributes, RuntimeModule decoratedModule, Int32 decoratedMetadataToken, RuntimeType attributeFilterType, Boolean mustBeInheritable, ListBuilder`1 derivedAttributes)
   at System.Reflection.CustomAttribute.GetCustomAttributes(RuntimeModule decoratedModule, Int32 decoratedMetadataToken, Int32 pcaCount, RuntimeType attributeFilterType)
   at System.Reflection.CustomAttribute.GetCustomAttributes(RuntimeParameterInfo parameter, RuntimeType caType)
   at System.Reflection.RuntimeParameterInfo.GetDefaultValueFromCustomAttributes()
   at System.Reflection.RuntimeParameterInfo.TryGetDefaultValueInternal(Boolean raw, Object& defaultValue)
   at System.Reflection.RuntimeParameterInfo.get_HasDefaultValue()
   at Microsoft.Azure.Functions.Worker.Definition.GrpcFunctionDefinition.<.ctor>b__2_7(ParameterInfo p) in D:\a\_work\1\s\src\DotNetWorker.Grpc\Definition\GrpcFunctionDefinition.cs:line 59
   at System.Linq.Enumerable.WhereSelectArrayIterator`2.ToArray()
   at System.Collections.Immutable.ImmutableArray.CreateRange[T](IEnumerable`1 items)
   at Microsoft.Azure.Functions.Worker.Definition.GrpcFunctionDefinition..ctor(FunctionLoadRequest loadRequest, IMethodInfoLocator methodInfoLocator) in D:\a\_work\1\s\src\DotNetWorker.Grpc\Definition\GrpcFunctionDefinition.cs:line 56
   at Microsoft.Azure.Functions.Worker.Rpc.RpcExtensions.ToFunctionDefinition(FunctionLoadRequest loadRequest, IMethodInfoLocator methodInfoLocator) in D:\a\_work\1\s\src\DotNetWorker.Grpc\RpcExtensions.cs:line 118
   at Microsoft.Azure.Functions.Worker.GrpcWorker.FunctionLoadRequestHandler(FunctionLoadRequest request, IFunctionsApplication application, IMethodInfoLocator methodInfoLocator) in D:\a\_work\1\s\src\DotNetWorker.Grpc\GrpcWorker.cs:line 268
Stack:    at System.ModuleHandle.ResolveType(QCallModule module, Int32 typeToken, IntPtr* typeInstArgs, Int32 typeInstCount, IntPtr* methodInstArgs, Int32 methodInstCount, ObjectHandleOnStack type)
   at System.ModuleHandle.ResolveTypeHandle(Int32 typeToken, RuntimeTypeHandle[] typeInstantiationContext, RuntimeTypeHandle[] methodInstantiationContext)
   at System.Reflection.RuntimeModule.ResolveType(Int32 metadataToken, Type[] genericTypeArguments, Type[] genericMethodArguments)
   at System.Reflection.CustomAttribute.FilterCustomAttributeRecord(MetadataToken caCtorToken, MetadataImport& scope, RuntimeModule decoratedModule, MetadataToken decoratedToken, RuntimeType attributeFilterType, Boolean mustBeInheritable, ListBuilder`1& derivedAttributes, RuntimeType& attributeType, IRuntimeMethodInfo& ctorWithParameters, Boolean& isVarArg)
   at System.Reflection.CustomAttribute.AddCustomAttributes(ListBuilder`1& attributes, RuntimeModule decoratedModule, Int32 decoratedMetadataToken, RuntimeType attributeFilterType, Boolean mustBeInheritable, ListBuilder`1 derivedAttributes)
   at System.Reflection.CustomAttribute.GetCustomAttributes(RuntimeModule decoratedModule, Int32 decoratedMetadataToken, Int32 pcaCount, RuntimeType attributeFilterType)
   at System.Reflection.CustomAttribute.GetCustomAttributes(RuntimeParameterInfo parameter, RuntimeType caType)
   at System.Reflection.RuntimeParameterInfo.GetDefaultValueFromCustomAttributes()
   at System.Reflection.RuntimeParameterInfo.TryGetDefaultValueInternal(Boolean raw, Object& defaultValue)
   at System.Reflection.RuntimeParameterInfo.get_HasDefaultValue()
   at Microsoft.Azure.Functions.Worker.Definition.GrpcFunctionDefinition.<.ctor>b__2_7(ParameterInfo p) in D:\a\_work\1\s\src\DotNetWorker.Grpc\Definition\GrpcFunctionDefinition.cs:line 59
   at System.Linq.Enumerable.WhereSelectArrayIterator`2.ToArray()
   at System.Collections.Immutable.ImmutableArray.CreateRange[T](IEnumerable`1 items)
   at Microsoft.Azure.Functions.Worker.Definition.GrpcFunctionDefinition..ctor(FunctionLoadRequest loadRequest, IMethodInfoLocator methodInfoLocator) in D:\a\_work\1\s\src\DotNetWorker.Grpc\Definition\GrpcFunctionDefinition.cs:line 56
   at Microsoft.Azure.Functions.Worker.Rpc.RpcExtensions.ToFunctionDefinition(FunctionLoadRequest loadRequest, IMethodInfoLocator methodInfoLocator) in D:\a\_work\1\s\src\DotNetWorker.Grpc\RpcExtensions.cs:line 118
   at Microsoft.Azure.Functions.Worker.GrpcWorker.FunctionLoadRequestHandler(FunctionLoadRequest request, IFunctionsApplication application, IMethodInfoLocator methodInfoLocator) in D:\a\_work\1\s\src\DotNetWorker.Grpc\GrpcWorker.cs:line 268 

[jviau]

@goldmelodyvn that call stack is not related to this issue. Please open a separate issue.

[nusliew]

@jviau Referring to this issue (#10251), may I know if there is an ETA for rollout? My host function version is 4.36 currently. Also, I would like to know any workaround is available?

[ali-asghar5]

An update on the roll out is highly appreciated. We are stuck now and need to resolve ASAP. Cheers

[russaram-bham]

@jviau has this update been merged and rolled out yet?

[jviau]

@russaram-bham a mitigation was checked in a while ago to address the shutdown scenario, which was the most common. Are you still seeing the Grpc.Core.RpcException from the Service Bus extension?

[TomONeill]

@jviau I am. Same problem as #10251.

Version that is ok:
Microsoft.Azure.Functions.Worker.Extensions.ServiceBus 5.20.0
Version that gave us the runtime exceptions:
Microsoft.Azure.Functions.Worker.Extensions.ServiceBus 5.24.0

Code:

internal sealed class AbcQueue
{ 
    [Function(nameof(AbcQueue))]
    public async Task RunAbcQueue(
    [ServiceBusTrigger(QueueNames.AbcQueue, AutoCompleteMessages = false, Connection = "ConnectionStrings:ServiceBus")]
    ServiceBusReceivedMessage message,
    ServiceBusMessageActions messageActions,
    FunctionContext context)
    {
        try { /**/ }
        catch (Exception ex)
        {
            logger.LogError(ex, "Error processing message ID: {id}", message.MessageId);

            await messageActions.DeadLetterMessageAsync(
                message,
                deadLetterReason: ErrorReasons.ProcessingError,
                deadLetterErrorDescription: $"Error processing message: {ex.Message}"
            );
        }
    }
}

Line the exception gets thrown: messageActions.DeadLetterMessageAsync.

Stacktrace:

Exception while executing function: Functions.AbcQueue Result: Failure
Type: 
Exception: System.AggregateException: One or more errors occurred. (Status(StatusCode="Unimplemented", Detail="Service is unimplemented."))
 ---> Grpc.Core.RpcException: Status(StatusCode="Unimplemented", Detail="Service is unimplemented.")
   at Microsoft.Azure.Functions.Worker.ServiceBusMessageActions.DeadLetterMessageAsync(ServiceBusReceivedMessage message, Dictionary`2 propertiesToModify, String deadLetterReason, String deadLetterErrorDescription, CancellationToken cancellationToken) in /_/extensions/Worker.Extensions.ServiceBus/src/ServiceBusMessageActions.cs:line 129
   at Abc.EventsAPI.Abc.AbcQueue.RunAbcQueue(ServiceBusReceivedMessage message, ServiceBusMessageActions messageActions, FunctionContext context) in /home/vsts/work/1/s/src/Abc.EventsAPI/Abc/AbcQueue.cs:line 68
   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
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
   at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionInvoker`2.<>c.<InvokeAsync>b__6_0(Task`1 t) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionInvoker.cs:line 32
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionExecutor.ExecuteAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionExecutor.cs:line 49
   at Abc.EventsAPI.DirectFunctionExecutor.ExecuteAsync(FunctionContext context) in /home/vsts/work/1/s/src/Abc.EventsAPI/obj/Release/net8.0/Microsoft.Azure.Functions.Worker.Sdk.Generators/Microsoft.Azure.Functions.Worker.Sdk.Generators.FunctionExecutorGenerator/GeneratedFunctionExecutor.g.cs:line 402
   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
   at Abc.EventsAPI.ScopedAttributeMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in /home/vsts/work/1/s/src/Abc.EventsAPI/ScopedAttribute.cs:line 71
   at Microsoft.Azure.Functions.Worker.FunctionsApplication.InvokeFunctionAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\FunctionsApplication.cs:line 96
   at Microsoft.Azure.Functions.Worker.Handlers.InvocationHandler.InvokeAsync(InvocationRequest request) in D:\a\_work\1\s\src\DotNetWorker.Grpc\Handlers\InvocationHandler.cs:line 89
Stack:    at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
   at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionInvoker`2.<>c.<InvokeAsync>b__6_0(Task`1 t) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionInvoker.cs:line 32
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionExecutor.ExecuteAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionExecutor.cs:line 49
   at Abc.EventsAPI.DirectFunctionExecutor.ExecuteAsync(FunctionContext context) in /home/vsts/work/1/s/src/Abc.EventsAPI/obj/Release/net8.0/Microsoft.Azure.Functions.Worker.Sdk.Generators/Microsoft.Azure.Functions.Worker.Sdk.Generators.FunctionExecutorGenerator/GeneratedFunctionExecutor.g.cs:line 402
   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
   at Abc.EventsAPI.ScopedAttributeMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in /home/vsts/work/1/s/src/Abc.EventsAPI/ScopedAttribute.cs:line 71
   at Microsoft.Azure.Functions.Worker.FunctionsApplication.InvokeFunctionAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\FunctionsApplication.cs:line 96
   at Microsoft.Azure.Functions.Worker.Handlers.InvocationHandler.InvokeAsync(InvocationRequest request) in D:\a\_work\1\s\src\DotNetWorker.Grpc\Handlers\InvocationHandler.cs:line 89 

Slightly altered for anonymisation

Version: .NET 8 Isolated
Runtime version: 4.1044.200.25476

[CSymes]

Glad to hear that this has been bumped up the backlog.
We've started encountering the same issue after updating from Microsoft.Azure.Functions.Worker.Extensions.ServiceBus v5.22.2 to v5.24.0 yesterday.

protected async Task CompleteServiceBusMessageAsync(ServiceBusReceiver receiver, ServiceBusReceivedMessage message)
{
    using var activity = _instrumentation.ActivitySource.StartServiceBusCompleteActivity(receiver, message)
        ?.SetStatus(ActivityStatusCode.Error);

    await receiver.CompleteMessageAsync(message);

    activity?.SetStatus(ActivityStatusCode.Ok);
}

Results in:

Grpc.Core.RpcException: Status(StatusCode="Unimplemented", Detail="Service is unimplemented.")
at Worker.ServiceBusMessageActions.CompleteMessageAsync(ServiceBusReceivedMessage message, CancellationToken cancellationToken) in src/ServiceBusMessageActions.cs:line 81
...

[FearNotDaniel]

@TomONeill @CSymes - I experienced the same after updating to 5.24.0 and assumed it was related to this issue - but the fix was actually more straightforward: after updating Microsoft.Azure.Functions.Worker to 2.51.0 and Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore to 2.1.0, the gRPC errors went away again.

[TomONeill]

Thanks @FearNotDaniel, that's actually very helpful. Will try that.