search

Azure / azure-functions-host

The host/runtime that powers Azure Functions
https://functions.azure.com
MIT License
1.93k stars 441 forks source link

Sometimes Python Function fails with InvalidOperationException / RpcFunctionInvocationDispatcherLoadBalancer.GetLanguageWorkerChannel #8921

Open martin-greentrax opened 1 year ago

martin-greentrax commented 1 year ago

This is on a Python 3.9 function with HTTPTrigger linked to a FastApi app. I have read through many similar issues but ours does not give a hint about how it would be related to our code nor does it happen consistently. It's only like 1-2% failure rate of all requests.

Investigative information

Please provide the following:

Event time 11/17/2022, 12:23:43.6081472 PM (Local time/UTC+1)
Message Exception while executing function: Functions.app Did not find any initialized language workers
Exception type System.InvalidOperationException
Failed method Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcherLoadBalancer.GetLanguageWorkerChannel Custom Properties LogLevel Error
Category Host.Results
HostInstanceId 8b22679e-e88e-4c24-ae92-68782ba42c6f
ProcessId 59
InvocationId 7d37df09-42d6-418d-b9a8-657b2ec8ae38
propStartTime 2022-11-17T11:23:41.5850000Z
propSucceeded False
propName app propTriggerReason This function was programmatically called via the host APIs.
propDuration 00:00:02.0100728
propEndTime 2022-11-17T11:23:43.5950000Z
propFullName Functions.app
propInvocationId 7d37df09-42d6-418d-b9a8-657b2ec8ae38

Call Stack

Microsoft.Azure.WebJobs.Host.FunctionInvocationException:
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<ExecuteWithLoggingAsync>d__26.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:352)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<TryExecuteAsync>d__18.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:108)
Inner exception System.InvalidOperationException handled at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw:
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcherLoadBalancer.GetLanguageWorkerChannel (Microsoft.Azure.WebJobs.Script, Version=4.13.0.0, Culture=neutral, PublicKeyToken=null: /src/azure-functions-host/src/WebJobs.Script/Workers/Rpc/FunctionRegistration/RpcFunctionInvocationDispatcherLoadBalancer.cs:27)
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher+<InvokeAsync>d__62.MoveNext (Microsoft.Azure.WebJobs.Script, Version=4.13.0.0, Culture=neutral, PublicKeyToken=null: /src/azure-functions-host/src/WebJobs.Script/Workers/Rpc/FunctionRegistration/RpcFunctionInvocationDispatcher.cs:466)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Script.Description.WorkerFunctionInvoker+<InvokeCore>d__9.MoveNext (Microsoft.Azure.WebJobs.Script, Version=4.13.0.0, Culture=neutral, PublicKeyToken=null: /src/azure-functions-host/src/WebJobs.Script/Description/Workers/WorkerFunctionInvoker.cs:95)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Script.Description.FunctionInvokerBase+<Invoke>d__24.MoveNext (Microsoft.Azure.WebJobs.Script, Version=4.13.0.0, Culture=neutral, PublicKeyToken=null: /src/azure-functions-host/src/WebJobs.Script/Description/FunctionInvokerBase.cs:82)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Script.Description.FunctionGenerator+<Coerce>d__3`1.MoveNext (Microsoft.Azure.WebJobs.Script, Version=4.13.0.0, Culture=neutral, PublicKeyToken=null: /src/azure-functions-host/src/WebJobs.Script/Description/FunctionGenerator.cs:225)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionInvoker`2+<InvokeAsync>d__10.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionInvoker.cs:52)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<InvokeWithTimeoutAsync>d__33.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:581)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<ExecuteWithWatchersAsync>d__32.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:527)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<ExecuteWithLoggingAsync>d__26.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:306)

**Logs/Traces**

11/17/2022, 12:23:57 PM
-
Trace
17-11-2022 11:23:57: INFO opencensus.ext.sqlalchemy.trace: Integrated module: sqlalchemy
Severity level: Information
11/17/2022, 12:23:45 PM
-
Trace
Worker process started and initialized.
Severity level: Information
11/17/2022, 12:23:45 PM
-
Trace
Adding jobhost language worker channel for runtime: python. workerId:e392dcdb-9860-43c8-9ca8-d3295f5e78f8
Severity level: Verbose
11/17/2022, 12:23:43 PM
-
Exception
Exception while executing function: Functions.app
Problem Id: System.InvalidOperationException at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcherLoadBalancer.GetLanguageWorkerChannel
11/17/2022, 12:23:43 PM
-
Trace
Executed 'Functions.app' (Failed, Id=7d37df09-42d6-418d-b9a8-657b2ec8ae38, Duration=1975ms)
Severity level: Error
11/17/2022, 12:23:43 PM
-
Exception
Exception while executing function: Functions.app
Problem Id: System.InvalidOperationException at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcherLoadBalancer.GetLanguageWorkerChannel
11/17/2022, 12:23:43 PM
-
Trace
Restarting worker channel for runtime: 'python'
Severity level: Verbose
11/17/2022, 12:23:43 PM
-
Trace
No initialized worker channels for runtime 'python'. Delaying future invocations
Severity level: Verbose
11/17/2022, 12:23:43 PM
-
Trace
Disposing language worker channel with id:e6de6303-c4d2-4427-9cd2-c1427a0a798e
Severity level: Verbose
11/17/2022, 12:23:43 PM
-
Trace
Executing 'Functions.app' (Reason='This function was programmatically called via the host APIs.', Id=7d37df09-42d6-418d-b9a8-657b2ec8ae38)
Severity level: Information
11/17/2022, 12:23:43 PM
-
Trace
Attempting to dispose webhost or jobhost channel for workerId: 'e6de6303-c4d2-4427-9cd2-c1427a0a798e', runtime: 'python'
Severity level: Verbose
11/17/2022, 12:23:43 PM
-
Trace
Handling WorkerErrorEvent for runtime:python, workerId:python. Failed with: Microsoft.Azure.WebJobs.Script.Workers.WorkerProcessExitException: python exited with code 137 (0x89) ---> System.Exception: 'x-ms-error-code': 'REDACTED', 'x-ms-error-code': 'REDACTED', 'x-ms-error-code': 'REDACTED' --- End of inner exception stack trace ---
Severity level: Verbose
11/17/2022, 12:23:41 PM
-
Trace
Request successfully matched the route with name 'app' and template '/{*route}'
Severity level: Verbose
11/17/2022, 12:23:41 PM
-
Request
app
URL: https://qaas-vehicles-test.azurewebsites.net/vehiclesResponse code: 500Response time: 2.1 s
11/17/2022, 12:23:30 PM
-
Trace
Executed 'Functions.app' (Succeeded, Id=cdc73e65-1945-42ee-9a5c-4e529c125b33, Duration=12ms)
Severity level: Information
11/17/2022, 12:23:30 PM
-
Request
URL: <empty>Response code: 0
Response time: <empty>
11/17/2022, 12:23:30 PM
-
Trace
17-11-2022 11:23:30: WARNING azure.functions.AsgiMiddleware: handle() is deprecated. Please `await .handle_async()` instead.
Severity level: Warning
11/17/2022, 12:23:30 PM
-
Trace
17-11-2022 11:23:30: WARNING azure.functions.AsgiMiddleware: handle() is deprecated. Please `await .handle_async()` instead.
Severity level: Warning

Repro steps

we cannot reproduce this. The exact same request with same payload will go through on a 2nd attept

Expected behavior

Don't fail randomly or show a proper error message and location

Actual behavior

It fails and does not show a proper error

Related information

Provide any related information 

cat host.json
{
  "version": "2.0",
  "logging": {
    "fileLoggingMode": "always",
    "logLevel": {
      "default": "Debug",
      "Host.Results": "Debug",
      "Function": "Debug",
      "Host.Aggregator": "Debug"
    },
    "applicationInsights": {
      "samplingSettings": {
        "isEnabled": true,
        "excludedTypes": "Request;Exception;Event;Trace"
      }
    }
  },
  "extensionBundle": {
    "id": "Microsoft.Azure.Functions.ExtensionBundle",
    "version": "[2.*, 3.0.0)"
  },
  "extensions": {
    "http": {
      "routePrefix": ""
    }
  }
}
ursaciuc-adrian commented 1 year ago

I am also encountering the same issue, but with C#. Are there any updates on this?

martin-greentrax commented 1 year ago

We see the same issue after having upgraded to python 3.10 :( How can we debug it? @kshyju