Azure / Azure/azure-functions-host
Invocations are still being processed while restart of grpc worker channel is in-progress
- Dominant language
- C#
- Stars
- 2k
- Forks
- 482
- Avg merge
- 2d 10h
- Merged PRs (30d)
- 36
Description
There seems to be a race condition when handling new messages when we are restarting a language worker channel. This came to attention while investigating [this CRI](https://portal.microsofticm.com/imp/v3/incidents/details/396987485/home) where customer function invocations were timing out and that caused our code to restart the language worker channel, but ~700ms after this, a new queue message is detected and and an invocation for that started - but ended up throwing "Did not find any initialized language workers" from the `GetLanguageWorkerChannel` method.
Full stack trace here:
> Microsoft.Azure.WebJobs.Host.FunctionInvocationException : Exception while executing function: Functions.ProcessProvisioningStateSyncWorkItem ---> System.InvalidOperationException : Did not find any initialized language workers
at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcherLoadBalancer.GetLanguageWorkerChannel(IEnumerable`1 rpcWorkerChannels) at /_/src/WebJobs.Script/Workers/Rpc/FunctionRegistration/RpcFunctionInvocationDispatcherLoadBalancer.cs : 27
at async Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.InvokeAsync(ScriptInvocationContext invocationContext) at /_/src/WebJobs.Script/Workers/Rpc/FunctionRegistration/RpcFunctionInvocationDispatcher.cs : 400
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Script.Description.WorkerFunctionInvoker.InvokeCore(Object[] parameters,FunctionInvocationContext context) at /_/src/WebJobs.Script/Description/Workers/WorkerFunctionInvoker.cs : 97
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Script.Description.FunctionInvokerBase.Invoke(Object[] parameters) at /_/src/WebJobs.Script/Description/FunctionInvokerBase.cs : 82
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Host.Executors.VoidTaskMethodInvoker`2.InvokeAsync[TReflected,TReturnType](TReflected instance,Object[] arguments) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\VoidTaskMethodInvoker.cs : 20
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Host.Executors.FunctionInvoker`2.InvokeAsync[TReflected,TReturnValue](Object instance,Object[] arguments) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionInvoker.cs : 52
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.InvokeWithTimeoutAsync(IFunctionInvoker invoker,ParameterHelper parameterHelper,CancellationTokenSource timeoutTokenSource,CancellationTokenSource functionCancellationTokenSource,Boolean throwOnTimeout,TimeSpan timerInterval,IFunctionInstance instance) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 581
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithWatchersAsync(IFunctionInstanceEx instance,ParameterHelper parameterHelper,ILogger logger,CancellationTokenSource functionCancellationTokenSource) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 527
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstanceEx instance,FunctionStartedMessage message,FunctionInstanceLogEntry instanceLogEntry,ParameterHelper parameterHelper,ILogger logger,CancellationToken cancellationToken) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 306
End of inner exception
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstanceEx instance,FunctionStartedMessage message,FunctionInstanceLogEntry instanceLogEntry,ParameterHelper parameterHelper,ILogger logger,CancellationToken cancellationToken) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 352
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryExecuteAsync(IFunctionInstance functionInstance,CancellationToken cancellationToken) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 108
Here is the screenshot of the data explaining the situation:
- 14:41:02.087 -The invocation timeout happens and we log that information.
- 14:41:02.089 - Disposing language worker channel.
- 14:41:02.742 - New queue message detected and starting the new invocation for that. Our code throws because at this time we do not have a healthy worker channel yet. Ideally we should be queueing up these new messages somewhere outside of the GrpcWorker channel so that they can be dequeued and processed once the channel is healthy.
Comment from @brettsam in the teams channel thread (_**CRI-> Executing new invocations while restarting language worker process - 08/03/2023**_)
> It seems like right before throwing this exception we should do a check to see "wait, are we restarting?!" and if so, do the same kind of backoff we do in DelayUntilFunctionDispatcherInitializedOrShutdown
The action item is to investigate this race and ensure the new messages are queued up outside of the grpc channel (which is being disposed).
Contributor guide
Research direction
Start in src/WebJobs.Script/Workers/Rpc/FunctionRegistration/RpcFunctionInvocationDispatcher.cs, especially InvokeAsync and GetLanguageWorkerChannel in RpcFunctionInvocationDispatcherLoadBalancer.cs. Compare the restart path with DelayUntilFunctionDispatcherInitializedOrShutdown and trace how queue messages enter during channel disposal. Done means new invocations no longer fail with "Did not find any initialized language workers" while the gRPC worker channel is restarting.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- csharp, grpc
- Domain
- backend, distributed-systems
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 38/100