azure-functions-python-worker: Python worker fails to start with "The operation has timed out"

The python process sometimes fails to start up with an operation time out. In one case, an execution started because of “RunOnStartup”, and the solution was for the process to start again. In a second case (reported below), we see that the process keeps failing to start with the same pattern:

[1/14/20 3:58:29 PM] Starting worker process failed
[1/14/20 3:58:29 PM] The operation has timed out.

Per @6403wency413: 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…

About this issue

  • Original URL
  • State: closed
  • Created 4 years ago
  • Comments: 64 (10 by maintainers)

Commits related to this issue

Most upvoted comments

Getting this also. Why is this issue closed? Is there a new issue we should be following. For me running func start works from the command line, but VS Code is totally to start the Azure python function itself. Eventually giving up with :Starting worker process failed. The operation has timed out"

After discussing with @mhoeger offline, we notice that the vscode-azurefunctions extension will not attach to the host process until Host lock lease acquired by instance ID is found code.

In Python case, the host emits the message Host lock lease acquired by instance ID when the Python interpreter starts. But the Python interpreter does NOT ignite the Python worker script directly, it starts the debugpy process first.

So, I think this issue is caused by

  1. The Python interpreter starts and loads the debugpy module (Python worker not yet started, --wait-for-client flag)
  2. The host emits Host lock lease acquired by instance ID message
  3. The VSCode Azure Functions Extension finishes in func-watch. As func: host start preLaunchTask is finished, now VSCode pass the control to ms.python extension for debugging.
  4. The VSCode debugger client attempts to attach to the debugpy server, however, since Python worker is not yet started, source code is not found, which causes the main Python interpreter process to fail immediately.
  5. Since the main Python interpreter process exit, the host throws an exception Starting worker process failed.

I’m also seeing this issue on MacOS. I haven’t tried it on Windows. It’s happening for both new and existing project. My venv is using Python 3.7.5.

It runs fine if I try to run using func start at the commandline, but then I can attach vs code to debug that running instance.

@dirkesquire, I just reverted to Azure Functions version 1.0.0 in VS Code and am able to debug now. @Hazhzeng please reopen this issue, this is not fixed in version 1.1.0.

Identical problem as @andrew-velez-trusight . Completely unable to start applications locally on MacOS running latest version of Core Tools and Functions.

Edit: I found my problem was caused by a ‘IsPastDue’ invocation by one of the functions. Setting ‘useMonitor’ to false allowed me to run the app locally. Maybe @Hazhzeng et al. could point towards/develop a full solution, rather than this workaround?

@Hazhzeng - The host lock lease acquisition is independent of the worker process starting, so that wouldn’t be the issue :\ As far as we’ve been able to tell, there’s some issue (likely race condition) with the “F5” debug experience of starting a function locally, but not with “func host start”.

@JB-NZ or others, do you have a project you could make public that is showing this behavior? Or does it happen even in the most basic cases (suggesting it’s something to do with the environment configuration)?

Trying to run a python azure function locally using VSCode, but it keeps shutting down

Trying to run a python azure function locally using VSCode, but it keeps shutting down with below errors, [27/05/2020 01:18:30] Starting worker process failed [27/05/2020 01:18:30] The operation has timed out.

Found Python version 3.7.6 (python3).

              %%%%%%
             %%%%%%
        @   %%%%%%    @
      @@   %%%%%%      @@
   @@@    %%%%%%%%%%%    @@@
 @@      %%%%%%%%%%        @@
   @@         %%%%       @@
     @@      %%%       @@
       @@    %%      @@
            %%
            %

Azure Functions Core Tools (2.7.2508 Commit hash: 4da36643c32783a832094318afcd679fa9d76455) Function Runtime Version: 2.0.13351.0 AZURE_FUNCTIONS_ENVIRONMENT: Development [27/05/2020 01:15:26] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:java [27/05/2020 01:15:26] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:powershell [27/05/2020 01:15:26] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:node [27/05/2020 01:15:26] Building host: startup suppressed: ‘False’, configuration suppressed: ‘False’, startup operation id: ‘5c6099b3-f738-4f74-9617-0ede842e2a1c’ [27/05/2020 01:15:26] Reading host configuration file ‘/Users/umeshraghavan/Documents/Python_Learning/Azure_Test/host.json’ [27/05/2020 01:15:26] Host configuration file read: [27/05/2020 01:15:26] { [27/05/2020 01:15:26] “version”: “2.0”, [27/05/2020 01:15:26] “extensionBundle”: { [27/05/2020 01:15:26] “id”: “Microsoft.Azure.Functions.ExtensionBundle”, [27/05/2020 01:15:26] “version”: “[1.*, 2.0.0)” [27/05/2020 01:15:26] } [27/05/2020 01:15:26] } [27/05/2020 01:15:26] Reading functions metadata [27/05/2020 01:15:26] 1 functions found [27/05/2020 01:15:26] Looking for extension bundle Microsoft.Azure.Functions.ExtensionBundle at /var/folders/z0/ps9_z2zd7vq1dgdp1q23sb5r0000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle [27/05/2020 01:15:27] Found a matching extension bundle at /var/folders/z0/ps9_z2zd7vq1dgdp1q23sb5r0000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1 [27/05/2020 01:15:27] Fetching information on versions of extension bundle Microsoft.Azure.Functions.ExtensionBundle available on https://functionscdn.azureedge.net/public/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/index.json [27/05/2020 01:15:27] Skipping bundle download since it already exists at path /var/folders/z0/ps9_z2zd7vq1dgdp1q23sb5r0000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1 [27/05/2020 01:15:27] Loading Extention bundle from /var/folders/z0/ps9_z2zd7vq1dgdp1q23sb5r0000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1 [27/05/2020 01:15:27] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:java [27/05/2020 01:15:27] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:powershell [27/05/2020 01:15:27] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:node [27/05/2020 01:15:28] Initializing Warmup Extension. [27/05/2020 01:15:28] Initializing Host. OperationId: ‘5c6099b3-f738-4f74-9617-0ede842e2a1c’. [27/05/2020 01:15:28] Host initialization: ConsecutiveErrors=0, StartupCount=1, OperationId=5c6099b3-f738-4f74-9617-0ede842e2a1c [27/05/2020 01:15:28] LoggerFilterOptions [27/05/2020 01:15:28] { [27/05/2020 01:15:28] “MinLevel”: “None”, [27/05/2020 01:15:28] “Rules”: [ [27/05/2020 01:15:28] { [27/05/2020 01:15:28] “ProviderName”: null, [27/05/2020 01:15:28] “CategoryName”: null, [27/05/2020 01:15:28] “LogLevel”: null, [27/05/2020 01:15:28] “Filter”: “<AddFilter>b__0” [27/05/2020 01:15:28] }, [27/05/2020 01:15:28] { [27/05/2020 01:15:28] “ProviderName”: “Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider”, [27/05/2020 01:15:28] “CategoryName”: null, [27/05/2020 01:15:28] “LogLevel”: “None”, [27/05/2020 01:15:28] “Filter”: null [27/05/2020 01:15:28] }, [27/05/2020 01:15:28] { [27/05/2020 01:15:28] “ProviderName”: “Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider”, [27/05/2020 01:15:28] “CategoryName”: null, [27/05/2020 01:15:28] “LogLevel”: null, [27/05/2020 01:15:28] “Filter”: “<AddFilter>b__0” [27/05/2020 01:15:28] } [27/05/2020 01:15:28] ] [27/05/2020 01:15:28] } [27/05/2020 01:15:28] FunctionResultAggregatorOptions [27/05/2020 01:15:28] { [27/05/2020 01:15:28] “BatchSize”: 1000, [27/05/2020 01:15:28] “FlushTimeout”: “00:00:30”, [27/05/2020 01:15:28] “IsEnabled”: true [27/05/2020 01:15:28] } [27/05/2020 01:15:28] SingletonOptions [27/05/2020 01:15:28] { [27/05/2020 01:15:28] “LockPeriod”: “00:00:15”, [27/05/2020 01:15:28] “ListenerLockPeriod”: “00:00:15”, [27/05/2020 01:15:28] “LockAcquisitionTimeout”: “10675199.02:48:05.4775807”, [27/05/2020 01:15:28] “LockAcquisitionPollingInterval”: “00:00:05”, [27/05/2020 01:15:28] “ListenerLockRecoveryPollingInterval”: “00:01:00” [27/05/2020 01:15:28] } [27/05/2020 01:15:28] HttpOptions [27/05/2020 01:15:28] { [27/05/2020 01:15:28] “DynamicThrottlesEnabled”: false, [27/05/2020 01:15:28] “MaxConcurrentRequests”: -1, [27/05/2020 01:15:28] “MaxOutstandingRequests”: -1, [27/05/2020 01:15:28] “RoutePrefix”: “api” [27/05/2020 01:15:28] } [27/05/2020 01:15:28] Starting JobHost [27/05/2020 01:15:28] Starting Host (HostId=1921681109-1141020319, InstanceId=b8d55010-7661-490f-a07c-8fa69ffc3a8f, Version=2.0.13351.0, ProcessId=86746, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=(null)) [27/05/2020 01:15:28] Loading functions metadata [27/05/2020 01:15:28] 1 functions loaded [27/05/2020 01:15:28] Loading proxies metadata [27/05/2020 01:15:28] Initializing Azure Function proxies [27/05/2020 01:15:29] 0 proxies loaded [27/05/2020 01:15:29] Starting worker process:python3 /Users/umeshraghavan/.vscode/extensions/ms-python.python-2020.5.80290/pythonFiles/lib/python/debugpy/no_wheels/debugpy --listen 127.0.0.1:9091 --wait-for-client “/usr/local/Cellar/azure-functions-core-tools/2.7.2508/workers/python/3.7/OSX/X64/worker.py” --host 127.0.0.1 --port 53389 --workerId 0c30d5db-7c6c-4969-8242-841bb3ef834c --requestId 25d1722e-a751-4cff-bb9d-274e02d05475 --grpcMaxMessageLength 134217728 [27/05/2020 01:15:29] python3 process with Id=86750 started [27/05/2020 01:15:29] Generating 1 job function(s) [27/05/2020 01:15:29] Found the following functions: [27/05/2020 01:15:29] Host.Functions.HttpTrigger1 [27/05/2020 01:15:29] [27/05/2020 01:15:30] Initializing function HTTP routes [27/05/2020 01:15:30] Mapped function route ‘api/HttpTrigger1’ [get,post] to ‘HttpTrigger1’ [27/05/2020 01:15:30] [27/05/2020 01:15:30] Host initialized (1601ms) [27/05/2020 01:15:30] Host started (1674ms) [27/05/2020 01:15:30] Job host started Hosting environment: Development Content root path: /Users/umeshraghavan/Documents/Python_Learning/Azure_Test Now listening on: http://0.0.0.0:7071 Application started. Press Ctrl+C to shut down.

Http Functions:

    HttpTrigger1: [GET,POST] http://localhost:7071/api/HttpTrigger1

[27/05/2020 01:15:35] Host lock lease acquired by instance ID ‘000000000000000000000000DAAA6D0A’. [27/05/2020 01:16:29] Starting worker process failed [27/05/2020 01:16:29] The operation has timed out. [27/05/2020 01:16:30] Starting worker process:python3 /Users/umeshraghavan/.vscode/extensions/ms-python.python-2020.5.80290/pythonFiles/lib/python/debugpy/no_wheels/debugpy --listen 127.0.0.1:9091 --wait-for-client “/usr/local/Cellar/azure-functions-core-tools/2.7.2508/workers/python/3.7/OSX/X64/worker.py” --host 127.0.0.1 --port 53389 --workerId 945c9b17-5aa1-4fbe-8e6c-6f9a44fde0c4 --requestId 4be76ccb-17a0-422b-9107-e5ddeb178f82 --grpcMaxMessageLength 134217728 [27/05/2020 01:16:30] python3 process with Id=86763 started [27/05/2020 01:17:30] Starting worker process failed [27/05/2020 01:17:30] The operation has timed out. [27/05/2020 01:17:30] Starting worker process:python3 /Users/umeshraghavan/.vscode/extensions/ms-python.python-2020.5.80290/pythonFiles/lib/python/debugpy/no_wheels/debugpy --listen 127.0.0.1:9091 --wait-for-client “/usr/local/Cellar/azure-functions-core-tools/2.7.2508/workers/python/3.7/OSX/X64/worker.py” --host 127.0.0.1 --port 53389 --workerId febbee78-f46c-4817-8a4a-e594f5790885 --requestId bb5da0ce-998e-4599-bdb3-7f0198397eac --grpcMaxMessageLength 134217728 [27/05/2020 01:17:30] python3 process with Id=86773 started [27/05/2020 01:18:30] Starting worker process failed [27/05/2020 01:18:30] The operation has timed out. [27/05/2020 01:18:30] Exceeded language worker restart retry count for runtime:python. Shutting down Functions Host [27/05/2020 01:18:30] Stopping host… [27/05/2020 01:18:30] Stopping JobHost [27/05/2020 01:18:30] Job host stopped [27/05/2020 01:18:30] Host shutdown completed. Application is shutting down…

@mhoeger I have never had this function working with the debugger (F5), I always get the issue with starting the worker process. Below is the line you asked for:

Starting worker process:python c:\Users\JB-NZ\.vscode\extensions\ms-python.python-2020.3.71659\pythonFiles\lib\python\debugpy\no_wheels\debugpy --listen 127.0.0.1:9091 --wait-for-client "C:\Users\JB-NZ\AppData\Local\chocoportable\lib\azure-functions-core-tools\tools\workers\python\3.7/WINDOWS/X64/worker.py" --host 127.0.0.1 --port 53404 --workerId e7c9f863-1e0f-4c2f-8f3e-01347cc68d38 --requestId 4b1f0921-d802-45ed-b853-41adbb05d35f --grpcMaxMessageLength 134217728

I’m also having this issue. When I run func host start it works, however when I use the F5 debug mode I get:

python process with Id=xxxxx started Starting worker process failed The operation has timed out.

I’m running python 3.7.5 64 bit on Windows. My function is using a service bus trigger. I’m not using a local storage emulator.

Is there any fix for this? It seems like it’s happening fairly regularly for people.

No it’s not MacOS specific. I get this way to often in Debian too.

@fisherjames have you actually encountered this ? Scope is very few people have encountered it very rarely. So go ahead and use it. 😃

I have encountered this, I get the errors “worker failed to start” and “did not find any initialized language workers”, running latest VS Code build on a MacBook Pro with latest OS updates.

I’m trying to write a function to query Twitter API using Tweepy and store tweets in Azure blob. If I can’t fix this issue then I will have to write a C# function with different Twitter library I suppose.

@6403wency413 Oops: I was using HttpTriggers.

If this helps, the configuration part of the log:

> Executing task: .venv/bin/python -m pip install -r requirements.txt <

Requirement already satisfied: azure-functions in ./.venv/lib/python3.7/site-packages (from -r requirements.txt (line 1)) (1.0.7)
WARNING: You are using pip version 19.2.3, however version 19.3.1 is available.
You should consider upgrading via the 'pip install --upgrade pip' command.

Terminal will be reused by tasks, press any key to close it.

> Executing task: . .venv/bin/activate && func host start <

Found Python version 3.7.5 (python).

                  %%%%%%
                 %%%%%%
            @   %%%%%%    @
          @@   %%%%%%      @@
       @@@    %%%%%%%%%%%    @@@
     @@      %%%%%%%%%%        @@
       @@         %%%%       @@
         @@      %%%       @@
           @@    %%      @@
                %%
                %

Azure Functions Core Tools (2.7.1948 Commit hash: 29a0626ded3ae99c4111f66763f27bb9fb564103)
Function Runtime Version: 2.0.12888.0
[1/14/20 3:56:18 PM] Building host: startup suppressed: 'False', configuration suppressed: 'False', startup operation id: '6f2ea23e-e323-4770-aee3-12c07b6f20c2'
[1/14/20 3:56:18 PM] Reading host configuration file '/Users/*************/Documents/AzureFunctions/host.json'
[1/14/20 3:56:18 PM] Host configuration file read:
[1/14/20 3:56:18 PM] {
[1/14/20 3:56:18 PM]   "version": "2.0",
[1/14/20 3:56:18 PM]   "extensionBundle": {
[1/14/20 3:56:18 PM]     "id": "Microsoft.Azure.Functions.ExtensionBundle",
[1/14/20 3:56:18 PM]     "version": "[1.*, 2.0.0)"
[1/14/20 3:56:18 PM]   }
[1/14/20 3:56:18 PM] }
[1/14/20 3:56:19 PM] Looking for extension bundle Microsoft.Azure.Functions.ExtensionBundle at /var/folders/lg/dqvppx796s55bxv86wls91c40000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle
[1/14/20 3:56:19 PM] Found a matching extension bundle at /var/folders/lg/dqvppx796s55bxv86wls91c40000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[1/14/20 3:56:19 PM] Fetching information on versions of extension bundle Microsoft.Azure.Functions.ExtensionBundle available on https://functionscdn.azureedge.net/public/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/index.json
[1/14/20 3:56:19 PM] Skipping bundle download since it already exists at path /var/folders/lg/dqvppx796s55bxv86wls91c40000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[1/14/20 3:56:19 PM] Loading Extention bundle from /var/folders/lg/dqvppx796s55bxv86wls91c40000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[1/14/20 3:56:19 PM] Reading functions metadata
[1/14/20 3:56:19 PM] 1 functions found
[1/14/20 3:56:19 PM] Loading startup extension 'ServiceBus'
[1/14/20 3:56:19 PM] Loaded extension 'ServiceBus' (3.2.0.0)
[1/14/20 3:56:24 PM] Initializing Warmup Extension.
[1/14/20 3:56:25 PM] Initializing Host. OperationId: '6f2ea23e-e323-4770-aee3-12c07b6f20c2'.
[1/14/20 3:56:25 PM] Host initialization: ConsecutiveErrors=0, StartupCount=1, OperationId=6f2ea23e-e323-4770-aee3-12c07b6f20c2
[1/14/20 3:56:25 PM] LoggerFilterOptions
[1/14/20 3:56:25 PM] {
[1/14/20 3:56:25 PM]   "MinLevel": "None",
[1/14/20 3:56:25 PM]   "Rules": [
[1/14/20 3:56:25 PM]     {
[1/14/20 3:56:25 PM]       "ProviderName": null,
[1/14/20 3:56:25 PM]       "CategoryName": null,
[1/14/20 3:56:25 PM]       "LogLevel": null,
[1/14/20 3:56:25 PM]       "Filter": "<AddFilter>b__0"
[1/14/20 3:56:25 PM]     },
[1/14/20 3:56:25 PM]     {
[1/14/20 3:56:25 PM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[1/14/20 3:56:25 PM]       "CategoryName": null,
[1/14/20 3:56:25 PM]       "LogLevel": "None",
[1/14/20 3:56:25 PM]       "Filter": null
[1/14/20 3:56:25 PM]     },
[1/14/20 3:56:25 PM]     {
[1/14/20 3:56:25 PM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[1/14/20 3:56:25 PM]       "CategoryName": null,
[1/14/20 3:56:25 PM]       "LogLevel": null,
[1/14/20 3:56:25 PM]       "Filter": "<AddFilter>b__0"
[1/14/20 3:56:25 PM]     }
[1/14/20 3:56:25 PM]   ]
[1/14/20 3:56:25 PM] }
[1/14/20 3:56:25 PM] FunctionResultAggregatorOptions
[1/14/20 3:56:25 PM] {
[1/14/20 3:56:25 PM]   "BatchSize": 1000,
[1/14/20 3:56:25 PM]   "FlushTimeout": "00:00:30",
[1/14/20 3:56:25 PM]   "IsEnabled": true
[1/14/20 3:56:25 PM] }
[1/14/20 3:56:25 PM] SingletonOptions
[1/14/20 3:56:25 PM] {
[1/14/20 3:56:25 PM]   "LockPeriod": "00:00:15",
[1/14/20 3:56:25 PM]   "ListenerLockPeriod": "00:00:15",
[1/14/20 3:56:25 PM]   "LockAcquisitionTimeout": "10675199.02:48:05.4775807",
[1/14/20 3:56:25 PM]   "LockAcquisitionPollingInterval": "00:00:05",
[1/14/20 3:56:25 PM]   "ListenerLockRecoveryPollingInterval": "00:01:00"
[1/14/20 3:56:25 PM] }
[1/14/20 3:56:25 PM] ServiceBusOptions
[1/14/20 3:56:25 PM] {
[1/14/20 3:56:25 PM]   "PrefetchCount": 0,
[1/14/20 3:56:25 PM]   "MessageHandlerOptions": {
[1/14/20 3:56:25 PM]     "AutoComplete": true,
[1/14/20 3:56:25 PM]     "MaxAutoRenewDuration": "00:05:00",
[1/14/20 3:56:25 PM]     "MaxConcurrentCalls": 64
[1/14/20 3:56:25 PM]   },
[1/14/20 3:56:25 PM]   "SessionHandlerOptions": {
[1/14/20 3:56:25 PM]     "AutoComplete": true,
[1/14/20 3:56:25 PM]     "MaxAutoRenewDuration": "00:05:00",
[1/14/20 3:56:25 PM]     "MaxConcurrentSessions": 2000,
[1/14/20 3:56:25 PM]     "MessageWaitTimeout": "00:01:00"
[1/14/20 3:56:25 PM]   }
[1/14/20 3:56:25 PM] }
[1/14/20 3:56:25 PM] HttpOptions
[1/14/20 3:56:25 PM] {
[1/14/20 3:56:25 PM]   "DynamicThrottlesEnabled": false,
[1/14/20 3:56:25 PM]   "MaxConcurrentRequests": -1,
[1/14/20 3:56:25 PM]   "MaxOutstandingRequests": -1,
[1/14/20 3:56:25 PM]   "RoutePrefix": "api"
[1/14/20 3:56:25 PM] }
[1/14/20 3:56:25 PM] Starting JobHost
[1/14/20 3:56:25 PM] Starting Host (HostId=macbookair1-653252612, InstanceId=e73612f7-3970-4e64-aad0-a35fd448b0af, Version=2.0.12888.0, ProcessId=18035, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=(null))
[1/14/20 3:56:25 PM] Loading functions metadata
[1/14/20 3:56:25 PM] 1 functions loaded
[1/14/20 3:56:25 PM] Loading proxies metadata
[1/14/20 3:56:26 PM] Initializing Azure Function proxies
[1/14/20 3:56:28 PM] 0 proxies loaded
[1/14/20 3:56: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 bd1f6995-dee4-4c02-9370-ba888b561b76 --requestId 7c60adf5-f1e6-4e14-87c6-e6306d25d78e --grpcMaxMessageLength 134217728
[1/14/20 3:56:29 PM] python process with Id=18071 started
[1/14/20 3:56:29 PM] Generating 1 job function(s)
[1/14/20 3:56:29 PM] Found the following functions:
[1/14/20 3:56:29 PM] Host.Functions.azurecleanupimages
[1/14/20 3:56:29 PM] 
[1/14/20 3:56:30 PM] Initializing function HTTP routes
[1/14/20 3:56:30 PM] No HTTP routes mapped
[1/14/20 3:56:30 PM] 
[1/14/20 3:56:30 PM] Host initialized (4558ms)
[1/14/20 3:56:30 PM] Host started (4777ms)
[1/14/20 3:56:30 PM] Job host started
Hosting environment: Production
Content root path: /Users/*************/Documents/AzureFunctions
Now listening on: http://0.0.0.0:7071