Skip to content

Python worker fails to start with "The operation has timed out" #607

@mhoeger

Description

@mhoeger

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...

Metadata

Metadata

Assignees

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions