Azure / Azure/azure-functions-host
Orphaned JobHost takes 29 minutes to dispose and ends up adding language worker channels
- Dominant language
- C#
- Stars
- 2k
- Forks
- 482
- Avg merge
- 2d 12h
- Merged PRs (30d)
- 38
Description
**CRI number: 472483572**
There is a host bug where an orphaned host instance is still trying to manage worker channels - this is leading to the new, active host instance not finding the new initialized worker channel. The logs show that the host took 29 minutes to dispose as it was waiting for the blob listener to stop (which itself took 29 minutes to stop). As a result, the orphaned host was still active in the background and adding/managing worker channels.
### Example
- The app is initialized and a new script host "2a0617b4" starts up without any issues, is able to handle invocations
- A restart was requested so host instance "2a0617b4" is shut down
- `Active host changing from '2a0617b4' to '(null)'`
- There are outstanding invocations so the now orphaned host "2a0617b4" finishes handling those invocations
- At the same time, we see a new language worker channel is being initialized
- `Adding webhost language worker channel for runtime: node. workerId:af7a65a6`
- And we see the orphaned host still working and loading functions
- `8 functions loaded`
- Another script host instance finally starts up and is marked active
- `Active host changing from '(null)' to '9823ea0e'`
- We then see the new host find the new channel and the orphan starting to shut down
```LOGS
2024-01-26T10:28:42.2051603Z - Found initialized language worker channel for runtime: node workerId:af7a65a6-89e9
2024-01-26T10:28:42.2354178Z - Host:9823ea0e Found initialized language worker channel for runtime: node workerId:af7a65a6
2024-01-26T10:28:42.4965886Z - Host:2a0617b4 Stopping JobHost
2024-01-26T10:28:42.7382463Z - Host:9823ea0e Job host started
2024-01-26T10:28:42.7411270Z - Host restarted (note: restart request from earlier complete)
```
- The new worker channel (af7a65a6) then crashes
- `Language Worker Process exited. Pid=16752. node exited with code 134 JavaScript heap out of memory`
- But this issue is handled by the orphaned host, not the new active host
```LOGS
2024-01-26T10:29:28.2418368Z - Host:2a0617b4 Handling WorkerErrorEvent for runtime
2024-01-26T10:29:28.2511918Z - Host:2a0617b4 Attempting to dispose webhost or jobhost channel for workerId: 'af7a65a6'
2024-01-26T10:29:28.2538382Z - Host:2a0617b4 No initialized worker channels for runtime 'node'. Delaying future invocations
2024-01-26T10:29:28.2538671Z - Host:2a0617b4 Restarting worker channel for runtime: 'node'
2024-01-26T10:29:28.2539376Z - Disposing WebHost channel for workerId: af7a65a6, for runtime:node
```
- We then start a new worker channel "0078bccb"
- And the active host final tries to handle the failure of the old worker channel but is not able to because the orphaned host already took care of it
```LOGS
2024-01-26T10:29:28.3508907Z - Host:9823ea0e Handling WorkerErrorEvent for runtime:node, workerId:node. Failed with: Microsoft.Azure.WebJobs.Script.Workers.WorkerProcessExitException: node exited with code 134
2024-01-26T10:29:28.3509787Z - Host:9823ea0e Attempting to dispose webhost or jobhost channel for workerId: 'af7a65a6', runtime: 'node'
2024-01-26T10:29:28.3510653Z - Host:9823ea0e Did not find WebHost or JobHost channel to dispose for workerId: 'af7a65a6', runtime: 'node'
2024-01-26T10:29:28.3511028Z - Host:9823ea0e Skipping worker channel restart for errored worker runtime: 'node', current runtime: 'node', isWebHostChannel: 'False', isJobHostChannel: 'False'
````
- When a new worker channel (0078bccb) finally comes up and is initialized, host 2a0617b4 is aware that it exists but the active host (9823ea0e) is not aware of this meaning that the channel was started on the wrong host
- This is when we start to see the "Did not find any initialized language workers" error
```LOGS
2024-01-26T10:29:32.0028809Z - Host:2a0617b4 Adding jobhost language worker channel for runtime: node. workerId:0078bccb
2024-01-26T10:29:32.0074856Z - Host:2a0617b4 Worker process started and initialized.
2024-01-26T10:29:33.1355781Z - Host:9823ea0e Did not find any initialized language workers
```
What should have happened is that the active host (9823ea0e) should have been the host that added the JobHost language worker and the orphaned host (2a0617b4) should have long stopped being active. We do see the log "Stopping JobHost" on the orphan but it takes a long time to shutdown, too long even:
- 10:28: `Stopping JobHost`
- 10:57: `Disposing ScriptHost` & `ScriptHost disposed`
It took 29 minutes for the orphaned host to be disposed. This is likely due to the blob listener taking a long time to dispose:
- 10:28:`Stopping the listener 'Microsoft.Azure.WebJobs.Host.Listeners.CompositeListener' for function 'BlobTrigger2'`
- 10:57: `Stopped the listener 'Microsoft.Azure.WebJobs.Host.Listeners.CompositeListener' for function 'BlobTrigger2'`
### Repro
See first comment below 👇
Contributor guide
Research direction
Start with the reproduction referenced in the first comment, then trace JobHost shutdown, blob listener disposal, and language worker channel management using the logs in this issue. Confirm that an orphaned host stops managing channels before the active host takes over, and verify that worker failures are handled by the active host.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- azure, csharp
- Domain
- backend, cloud
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100