search

Azure / azure-functions-host

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

Don't allow invocations on failed language worker startup #5233

Open yojagad opened 4 years ago

yojagad commented 4 years ago

Today, we wait for the function dispatcher to initialize failing which we still allow invocations. This ends up with the each invocation resulting in "Did not find any initialized language worker" errors. There needs to be a tighter loop around it and possibly not allow invocations at all in cases where there are no initialized language workers.

Exception stack trace:

System.InvalidOperationException : Did not find any initialized language workers
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcherLoadBalancer.GetLanguageWorkerChannel(IEnumerable`1 rpcWorkerChannels,Int32 maxProcessCount) at C:\azure-webjobs-sdk-script\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcherLoadBalancer.cs : 27
   at async Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.InvokeAsync(ScriptInvocationContext invocationContext) at C:\azure-webjobs-sdk-script\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs : 236
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at async Microsoft.Azure.WebJobs.Script.Description.WorkerFunctionInvoker.InvokeCore(Object[] parameters,FunctionInvocationContext context) at C:\azure-webjobs-sdk-script\src\WebJobs.Script\Description\Workers\WorkerFunctionInvoker.cs : 81
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at async Microsoft.Azure.WebJobs.Script.Description.FunctionInvokerBase.Invoke(Object[] parameters) at C:\azure-webjobs-sdk-script\src\WebJobs.Script\Description\FunctionInvokerBase.cs : 85
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at async Microsoft.Azure.WebJobs.Script.Description.FunctionGenerator.Coerce[T](Task`1 src) at C:\azure-webjobs-sdk-script\src\WebJobs.Script\Description\FunctionGenerator.cs : 225
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at async Microsoft.Azure.WebJobs.Host.Executors.FunctionInvoker`2.InvokeAsync[TReflected,TReturnValue](Object instance,Object[] arguments) at C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionInvoker.cs : 52
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.InvokeAsync(IFunctionInvoker invoker,ParameterHelper parameterHelper,CancellationTokenSource timeoutTokenSource,CancellationTokenSource functionCancellationTokenSource,Boolean throwOnTimeout,TimeSpan timerInterval,IFunctionInstance instance) at C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 587
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithWatchersAsync(IFunctionInstanceEx instance,ParameterHelper parameterHelper,ILogger logger,CancellationTokenSource functionCancellationTokenSource) at C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 532
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(??) at C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 470
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(??) at C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 278
pragnagopa commented 4 years ago

We should shutdown Host if language worker never starts

yojagad commented 4 years ago

Had a discussion with Fabio about this and it requires additional, follow up conversations.

mhoeger commented 4 years ago

More details on this issue too (same root cause): https://github.com/Azure/azure-functions-host/issues/5367

erwinsalubre commented 4 years ago

I have the same issue with ServiceBusTrigger with an output below.

[1/14/20 3:56:34 PM] Executing 'Functions.azurecleanupimages' (Reason='New ServiceBus message detected on 'iri6-servicebusqtest'.', Id=3a8610b8-cfdd-4151-9a6c-ab2e649bc111) [1/14/20 3:56:34 PM] Trigger Details: MessageId: db791f7052684d7997a75d092f4cf6e1, DeliveryCount: 1, EnqueuedTime: 1/14/20 3:56:25 PM, LockedUntil: 1/14/20 4:01:27 PM, SessionId: (null) [1/14/20 3:57:29 PM] Starting worker process failed [1/14/20 3:57:29 PM] The operation has timed out. [1/14/20 3:57:29 PM] Starting worker process:python /Users/**/.vscode/extensions/ms-python.python-2020.1.57204/pythonFiles/ptvsd_launcher.py --default --host 127.0.0.1 --port 9091 --wait "/usr/local/Cellar/azure-functions-core-tools/2.7.1948/workers/python/3.7/OSX/X64/worker.py" --host 127.0.0.1 --port 65522 --workerId f03ddfda-8755-47ef-bea4-5f773263a205 --requestId c31e8c64-6fda-4f9d-bc4d-a7eb4312f39b --grpcMaxMessageLength 134217728 [1/14/20 3:57:29 PM] python process with Id=18081 started [1/14/20 3:57:29 PM] Executed 'Functions.azurecleanupimages' (Failed, Id=3a8610b8-cfdd-4151-9a6c-ab2e649bc111) [1/14/20 3:57:29 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:29 PM] Message processing error (Action=UserCallback, ClientId=MessageReceiver1iri6-servicebusqtest, EntityPath=iri6-servicebusqtest, Endpoint=iri6-servicebusnstest.servicebus.windows.net) [1/14/20 3:57:29 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:29 PM] Executing 'Functions.azurecleanupimages' (Reason='New ServiceBus message detected on 'iri6-servicebusqtest'.', Id=755bec73-3bc2-417f-90f0-139dfe7fa9a8) [1/14/20 3:57:29 PM] Trigger Details: MessageId: db791f7052684d7997a75d092f4cf6e1, DeliveryCount: 2, EnqueuedTime: 1/14/20 3:56:25 PM, LockedUntil: 1/14/20 4:02:23 PM, SessionId: (null) [1/14/20 3:57:29 PM] Executed 'Functions.azurecleanupimages' (Failed, Id=755bec73-3bc2-417f-90f0-139dfe7fa9a8) [1/14/20 3:57:29 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:29 PM] Message processing error (Action=UserCallback, ClientId=MessageReceiver1iri6-servicebusqtest, EntityPath=iri6-servicebusqtest, Endpoint=iri6-servicebusnstest.servicebus.windows.net) [1/14/20 3:57:29 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:29 PM] Executing 'Functions.azurecleanupimages' (Reason='New ServiceBus message detected on 'iri6-servicebusqtest'.', Id=a22e1407-70f1-4c42-aea1-ceb71c234011) [1/14/20 3:57:29 PM] Trigger Details: MessageId: db791f7052684d7997a75d092f4cf6e1, DeliveryCount: 3, EnqueuedTime: 1/14/20 3:56:25 PM, LockedUntil: 1/14/20 4:02:23 PM, SessionId: (null) [1/14/20 3:57:29 PM] Executed 'Functions.azurecleanupimages' (Failed, Id=a22e1407-70f1-4c42-aea1-ceb71c234011) [1/14/20 3:57:29 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:29 PM] Message processing error (Action=UserCallback, ClientId=MessageReceiver1iri6-servicebusqtest, EntityPath=iri6-servicebusqtest, Endpoint=iri6-servicebusnstest.servicebus.windows.net) [1/14/20 3:57:29 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:29 PM] Executing 'Functions.azurecleanupimages' (Reason='New ServiceBus message detected on 'iri6-servicebusqtest'.', Id=9a2b5e59-0c80-4955-b40f-a0fa6acbada5) [1/14/20 3:57:29 PM] Trigger Details: MessageId: db791f7052684d7997a75d092f4cf6e1, DeliveryCount: 4, EnqueuedTime: 1/14/20 3:56:25 PM, LockedUntil: 1/14/20 4:02:23 PM, SessionId: (null) [1/14/20 3:57:29 PM] Executed 'Functions.azurecleanupimages' (Failed, Id=9a2b5e59-0c80-4955-b40f-a0fa6acbada5) [1/14/20 3:57:29 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:29 PM] Message processing error (Action=UserCallback, ClientId=MessageReceiver1iri6-servicebusqtest, EntityPath=iri6-servicebusqtest, Endpoint=iri6-servicebusnstest.servicebus.windows.net) [1/14/20 3:57:29 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Executing 'Functions.azurecleanupimages' (Reason='New ServiceBus message detected on 'iri6-servicebusqtest'.', Id=25f0a5b8-0d3e-4575-8aa5-eacce3f129bf) [1/14/20 3:57:30 PM] Trigger Details: MessageId: db791f7052684d7997a75d092f4cf6e1, DeliveryCount: 5, EnqueuedTime: 1/14/20 3:56:25 PM, LockedUntil: 1/14/20 4:02:23 PM, SessionId: (null) [1/14/20 3:57:30 PM] Executed 'Functions.azurecleanupimages' (Failed, Id=25f0a5b8-0d3e-4575-8aa5-eacce3f129bf) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Message processing error (Action=UserCallback, ClientId=MessageReceiver1iri6-servicebusqtest, EntityPath=iri6-servicebusqtest, Endpoint=iri6-servicebusnstest.servicebus.windows.net) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Executing 'Functions.azurecleanupimages' (Reason='New ServiceBus message detected on 'iri6-servicebusqtest'.', Id=aa16462a-d7fb-4f39-b879-addfab270a39) [1/14/20 3:57:30 PM] Trigger Details: MessageId: db791f7052684d7997a75d092f4cf6e1, DeliveryCount: 6, EnqueuedTime: 1/14/20 3:56:25 PM, LockedUntil: 1/14/20 4:02:23 PM, SessionId: (null) [1/14/20 3:57:30 PM] Executed 'Functions.azurecleanupimages' (Failed, Id=aa16462a-d7fb-4f39-b879-addfab270a39) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Message processing error (Action=UserCallback, ClientId=MessageReceiver1iri6-servicebusqtest, EntityPath=iri6-servicebusqtest, Endpoint=iri6-servicebusnstest.servicebus.windows.net) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Executing 'Functions.azurecleanupimages' (Reason='New ServiceBus message detected on 'iri6-servicebusqtest'.', Id=f5b835e8-737b-4c1d-adab-ea8da75368d6) [1/14/20 3:57:30 PM] Trigger Details: MessageId: db791f7052684d7997a75d092f4cf6e1, DeliveryCount: 7, EnqueuedTime: 1/14/20 3:56:25 PM, LockedUntil: 1/14/20 4:02:23 PM, SessionId: (null) [1/14/20 3:57:30 PM] Executed 'Functions.azurecleanupimages' (Failed, Id=f5b835e8-737b-4c1d-adab-ea8da75368d6) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Message processing error (Action=UserCallback, ClientId=MessageReceiver1iri6-servicebusqtest, EntityPath=iri6-servicebusqtest, Endpoint=iri6-servicebusnstest.servicebus.windows.net) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Executing 'Functions.azurecleanupimages' (Reason='New ServiceBus message detected on 'iri6-servicebusqtest'.', Id=177a95b6-c3fc-4842-83ba-f2f5a707e4dc) [1/14/20 3:57:30 PM] Trigger Details: MessageId: db791f7052684d7997a75d092f4cf6e1, DeliveryCount: 8, EnqueuedTime: 1/14/20 3:56:25 PM, LockedUntil: 1/14/20 4:02:24 PM, SessionId: (null) [1/14/20 3:57:30 PM] Executed 'Functions.azurecleanupimages' (Failed, Id=177a95b6-c3fc-4842-83ba-f2f5a707e4dc) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Message processing error (Action=UserCallback, ClientId=MessageReceiver1iri6-servicebusqtest, EntityPath=iri6-servicebusqtest, Endpoint=iri6-servicebusnstest.servicebus.windows.net) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Executing 'Functions.azurecleanupimages' (Reason='New ServiceBus message detected on 'iri6-servicebusqtest'.', Id=ecbaea2b-8c7e-402f-b569-a50f57759334) [1/14/20 3:57:30 PM] Trigger Details: MessageId: db791f7052684d7997a75d092f4cf6e1, DeliveryCount: 9, EnqueuedTime: 1/14/20 3:56:25 PM, LockedUntil: 1/14/20 4:02:24 PM, SessionId: (null) [1/14/20 3:57:30 PM] Executed 'Functions.azurecleanupimages' (Failed, Id=ecbaea2b-8c7e-402f-b569-a50f57759334) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Message processing error (Action=UserCallback, ClientId=MessageReceiver1iri6-servicebusqtest, EntityPath=iri6-servicebusqtest, Endpoint=iri6-servicebusnstest.servicebus.windows.net) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Executing 'Functions.azurecleanupimages' (Reason='New ServiceBus message detected on 'iri6-servicebusqtest'.', Id=f37c51cd-07dc-4b60-88b9-24c8cb5bf3c2) [1/14/20 3:57:30 PM] Trigger Details: MessageId: db791f7052684d7997a75d092f4cf6e1, DeliveryCount: 10, EnqueuedTime: 1/14/20 3:56:25 PM, LockedUntil: 1/14/20 4:02:24 PM, SessionId: (null) [1/14/20 3:57:30 PM] Executed 'Functions.azurecleanupimages' (Failed, Id=f37c51cd-07dc-4b60-88b9-24c8cb5bf3c2) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:57:30 PM] Message processing error (Action=UserCallback, ClientId=MessageReceiver1iri6-servicebusqtest, EntityPath=iri6-servicebusqtest, Endpoint=iri6-servicebusnstest.servicebus.windows.net) [1/14/20 3:57:30 PM] System.Private.CoreLib: Exception while executing function: Functions.azurecleanupimages. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/14/20 3:58:29 PM] Starting worker process failed [1/14/20 3:58:29 PM] The operation has timed out. [1/14/20 3:58:29 PM] Starting worker process:python /Users/****/.vscode/extensions/ms-python.python-2020.1.57204/pythonFiles/ptvsd_launcher.py --default --host 127.0.0.1 --port 9091 --wait "/usr/local/Cellar/azure-functions-core-tools/2.7.1948/workers/python/3.7/OSX/X64/worker.py" --host 127.0.0.1 --port 65522 --workerId 176e1989-b35c-4a88-92af-18309646b17f --requestId 46326407-b8a5-4cf1-8620-d7e60964261c --grpcMaxMessageLength 134217728 [1/14/20 3:58:29 PM] python process with Id=18089 started [1/14/20 3:59:29 PM] Starting worker process failed [1/14/20 3:59:29 PM] The operation has timed out. [1/14/20 3:59:29 PM] Exceeded language worker restart retry count for runtime:python. Shutting down Functions Host [1/14/20 3:59:29 PM] Stopping host... [1/14/20 3:59:29 PM] Stopping JobHost [1/14/20 3:59:29 PM] Job host stopped [1/14/20 3:59:29 PM] Host shutdown completed. Application is shutting down...

mhoeger commented 4 years ago

@6403wency413 - I think your issue has the same symptoms but is slightly different - it looks python process always fails to start with a timeout. Even with the fix mentioned for this issue, you would continue to see your function app crash - just with a different error. Moving your issue details over here: https://github.com/Azure/azure-functions-python-worker/issues/607

toddhaugen commented 4 years ago

I think this needs to be reopened. I am having what appears to be the same problem with an http trigger. I upgraded to the latest Azure function both core tools and plug in. This is blocking as I cannot debug python locally to fix my bug. I show no local changes to any project files so I think this is an SDK issue.

def main(req: func.HttpRequest) -> func.HttpResponse: logging.info('Python HTTP trigger function processed a request.')

[1/16/2020 6:10:07 AM] Executing HTTP request: { [1/16/2020 6:10:07 AM] "requestId": "1d23c80f-cebf-41d5-b28b-625b9c3bad4d", [1/16/2020 6:10:07 AM] "method": "GET", [1/16/2020 6:10:07 AM] "uri": "/api/EvaluateData" [1/16/2020 6:10:07 AM] } [1/16/2020 6:10:08 AM] Executing 'Functions.EvaluateData' (Reason='This function was programmatically called via the host APIs.', Id=236b76e2-88af-47e5-b192-280e00073f67) [1/16/2020 6:10:10 AM] Executing HTTP request: { [1/16/2020 6:10:10 AM] "requestId": "c675aced-fda1-4d37-850b-9b09801bb919", [1/16/2020 6:10:10 AM] "method": "GET", [1/16/2020 6:10:10 AM] "uri": "/api/EvaluateData" [1/16/2020 6:10:10 AM] } [1/16/2020 6:10:10 AM] Executing 'Functions.EvaluateData' (Reason='This function was programmatically called via the host APIs.', Id=c6f1ae3c-e47b-4b28-8c49-548a4bcb1813) [1/16/2020 6:10:44 AM] Starting worker process failed [1/16/2020 6:10:44 AM] The operation has timed out. [1/16/2020 6:10:44 AM] Starting worker process:python c:/Users/thaugen/.vscode/extensions/ms-python.python-2020.1.58038/pythonFiles/ptvsd_launcher.py --default --host 127.0.0.1 --port 9091 --wait "C:\Users\thaugen\AppData\Roaming\npm\node_modules\azure-functions-core-tools\bin\workers\python\3.6/WINDOWS/X64/worker.py" --host 127.0.0.1 --port 55528 --workerId 1d30e6e6-151b-45a8-ba60-e01a90762692 --requestId 03922321-2fe0-4967-b5c3-9ada9ed84bc1 --grpcMaxMessageLength 134217728 [1/16/2020 6:10:44 AM] python process with Id=10344 started [1/16/2020 6:10:44 AM] Executed 'Functions.EvaluateData' (Failed, Id=c6f1ae3c-e47b-4b28-8c49-548a4bcb1813) [1/16/2020 6:10:44 AM] Executed 'Functions.EvaluateData' (Failed, Id=236b76e2-88af-47e5-b192-280e00073f67) [1/16/2020 6:10:44 AM] System.Private.CoreLib: Exception while executing function: Functions.EvaluateData. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/16/2020 6:10:44 AM] System.Private.CoreLib: Exception while executing function: Functions.EvaluateData. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers. [1/16/2020 6:10:44 AM] Executed HTTP request: { [1/16/2020 6:10:44 AM] Executed HTTP request: { [1/16/2020 6:10:44 AM] "requestId": "c675aced-fda1-4d37-850b-9b09801bb919", [1/16/2020 6:10:44 AM] "requestId": "1d23c80f-cebf-41d5-b28b-625b9c3bad4d", [1/16/2020 6:10:44 AM] "method": "GET",[1/16/2020 6:10:44 AM] "method": "GET", [1/16/2020 6:10:44 AM] "uri": "/api/EvaluateData",

[1/16/2020 6:10:44 AM] "uri": "/api/EvaluateData", [1/16/2020 6:10:44 AM] "identities": [ [1/16/2020 6:10:44 AM] "identities": [[1/16/2020 6:10:44 AM] {

[1/16/2020 6:10:44 AM] "type": "WebJobsAuthLevel",[1/16/2020 6:10:44 AM] {

[1/16/2020 6:10:44 AM] "level": "Admin" [1/16/2020 6:10:44 AM] "type": "WebJobsAuthLevel",[1/16/2020 6:10:44 AM] } [1/16/2020 6:10:44 AM] ],

[1/16/2020 6:10:44 AM] "level": "Admin"[1/16/2020 6:10:44 AM] "status": 500,

[1/16/2020 6:10:44 AM] "duration": 37177[1/16/2020 6:10:44 AM] } [1/16/2020 6:10:44 AM] ],

[1/16/2020 6:10:44 AM] } [1/16/2020 6:10:44 AM] "status": 500, [1/16/2020 6:10:44 AM] "duration": 34203 [1/16/2020 6:10:44 AM] } [1/16/2020 6:11:44 AM] Starting worker process failed [1/16/2020 6:11:44 AM] The operation has timed out. [1/16/2020 6:11:44 AM] Starting worker process:python c:/Users/thaugen/.vscode/extensions/ms-python.python-2020.1.58038/pythonFiles/ptvsd_launcher.py --default --host 127.0.0.1 --port 9091 --wait "C:\Users\thaugen\AppData\Roaming\npm\node_modules\azure-functions-core-tools\bin\workers\python\3.6/WINDOWS/X64/worker.py" --host 127.0.0.1 --port 55528 --workerId 74efeb8b-3957-4af0-92a5-2e93575ecf93 --requestId 4532fe0c-109a-46cf-9d28-0db71deed6f6 --grpcMaxMessageLength 134217728 [1/16/2020 6:11:44 AM] python process with Id=9416 started [1/16/2020 6:12:44 AM] Starting worker process failed [1/16/2020 6:12:44 AM] The operation has timed out. [1/16/2020 6:12:44 AM] Exceeded language worker restart retry count for runtime:python. Shutting down Functions Host [1/16/2020 6:12:44 AM] Stopping host... [1/16/2020 6:12:44 AM] Stopping JobHost [1/16/2020 6:12:44 AM] Job host stopped [1/16/2020 6:12:44 AM] Host shutdown completed. Application is shutting down...

mhoeger commented 4 years ago

@toddhaugen - what did you upgrade your core tools version from and to? Note that the symptom of functions failing with that specific error has a fixed checked in but not released yet. The error you are facing seems to be this one: https://github.com/Azure/azure-functions-python-worker/issues/607

Can you post those details on that issue and follow there?

mhoeger commented 4 years ago

Re-opening, we should not treat "Did not find initialized language workers" as a invocation exception. There are likely other gaps to patch, but this will at least ensure that the invocation will be correctly retried (for non-http triggers)

mhoeger commented 4 years ago

This pr (https://github.com/Azure/azure-functions-host/pull/5803) was meant to address this issue. However, it looks like exceptions raised in InvokeAsync are still being handled as user exceptions somewhere in the pipeline. This happened for this exception too: https://github.com/Azure/azure-functions-host/issues/6022