Azure / Azure/azure-functions-host

Worker startup timeout during .NET isolated metadata indexing immediately exceeds retry count instead of retrying

Open
#11,871 0 comments 1 reaction 0 assignees View on GitHub
Needs: Triage (Functions)
Dominant language
C#
Stars
2k
Forks
482
Avg merge
2d 10h
Merged PRs (30d)
36

Description

## Summary

When a .NET isolated worker process times out before sending `StartStream` during worker metadata indexing, the host appears to enter the normal worker restart path but immediately logs `Exceeded language worker restart retry count` after the first timeout. No second or third worker process start attempt is visible.

This looks like a retry-flow bug/gap: the failing channel is a webhost language worker channel created by `WorkerFunctionMetadataProvider` for worker indexing, but the timeout is handled by `RpcFunctionInvocationDispatcher` before that dispatcher has initialized its retry threshold from function metadata. As a result, `ErrorEventsThreshold` is still `0`, so the first `WorkerErrorEvent` is treated as exceeding the retry limit.

## Expected behavior

If a worker process starts but does not send `StartStream` within `ProcessStartupTimeout` during metadata indexing, the host should retry worker startup according to the configured retry policy, e.g. `3 * ProcessCount`, or otherwise have a metadata-indexing-specific retry path.

At minimum, the first timeout should not immediately be treated as retry exhaustion.

## Actual behavior

For the observed .NET isolated startup timeout, the host:

1. Started a webhost language worker channel for metadata indexing.
2. Started the worker process.
3. Timed out waiting for `StartStream` after ~60s.
4. Published/handled `WorkerErrorEvent`.
5. Logged `Restarting worker channel`.
6. Immediately logged `Exceeded language worker restart retry count`.
7. Did not start a replacement worker process.
8. The original worker sent `StartStream` shortly after the timeout, but it was too late to recover.

## Observed evidence

Example sanitized app/worker/timeframe from production logs:

- App: ``
- Stamp: ``
- Role instance: ``
- Time: `2026-06-09T13:22Z` - `13:24Z`
- Runtime: `dotnet-isolated`

Relevant log sequence:

| Time UTC | Source | Summary |
|---|---|---|
| `13:22:55.395` | `Microsoft.Azure.WebJobs.Script.WorkerFunctionMetadataProvider` | `Fetching metadata for workerRuntime: dotnet-isolated` |
| `13:22:55.396` | `Microsoft.Azure.WebJobs.Script.WorkerFunctionMetadataProvider` | `JobHost is starting with state 'Default'. Initializing worker channel.` |
| `13:22:55.396` | `Microsoft.Azure.WebJobs.Script.Workers.Rpc.WebHostRpcWorkerChannelManager` | `Initializing language worker channel for runtime:dotnet-isolated` |
| `13:22:55.397` | `Microsoft.Azure.WebJobs.Script.Workers.Rpc.WebHostRpcWorkerChannelManager` | `Creating language worker channel for runtime:dotnet-isolated` |
| `13:22:55.407` | `Microsoft.Azure.WebJobs.Script.Workers.Rpc.WebHostRpcWorkerChannelManager` | `Adding webhost language worker channel for runtime: dotnet-isolated. workerId:9022c7d1-161f-4ab2-a491-df0ea23f4716` |
| `13:22:55.415` | `Worker.LanguageWorkerChannel.dotnet-isolated.9022c7d1-161f-4ab2-a491-df0ea23f4716` | `Initiating Worker Process start up` |
| `13:22:57.507` | `Worker.rpcWorkerProcess.dotnet-isolated.9022c7d1-161f-4ab2-a491-df0ea23f4716` | `C:\home\site\wwwroot\.exe process with Id=8588 started` |
| `13:23:55.830` | `Worker.LanguageWorkerChannel.dotnet-isolated.9022c7d1-161f-4ab2-a491-df0ea23f4716` | `Starting worker process failed` |
| `13:23:55.836` | `Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher` | `Handling WorkerErrorEvent for runtime:dotnet-isolated ... System.TimeoutException` |
| `13:23:55.837` | `Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher` | `Attempting to dispose webhost or jobhost channel for workerId: '9022c7d1-161f-4ab2-a491-df0ea23f4716', runtime: 'dotnet-isolated'` |
| `13:23:55.841` | `Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher` | `No initialized worker channels for runtime 'dotnet-isolated'. Delaying future invocations` |
| `13:23:55.841` | `Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher` | `Restarting worker channel for runtime: 'dotnet-isolated'` |
| `13:23:55.846` | `Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher` | `Exceeded language worker restart retry count for runtime:dotnet-isolated. Shutting down and proactively recycling the Functions Host to recover` |
| `13:23:55.848` | `Microsoft.Azure.WebJobs.Script.Workers.Rpc.WebHostRpcWorkerChannelManager` | `Failed to start language worker process for runtime: dotnet-isolated. workerId:9022c7d1-161f-4ab2-a491-df0ea23f4716` |
| `13:23:55.852` | `Microsoft.Azure.WebJobs.Script.Workers.Rpc.WebHostRpcWorkerChannelManager` | `Failed to initialize webhost language worker channel for runtime: dotnet-isolated. workerId:9022c7d1-161f-4ab2-a491-df0ea23f4716` |
| `13:24:07.606` | `Worker.LanguageWorkerChannel.dotnet-isolated.9022c7d1-161f-4ab2-a491-df0ea23f4716` | `[channel] received 9022c7d1-161f-4ab2-a491-df0ea23f4716: StartStream` |

There was only one visible process start attempt for this app/worker:

| Signal | Count |
|---|---:|
| `Initiating Worker Process start up` | 1 |
| `process with Id=... started` | 1 |
| `Starting worker process failed` | 1 |
| `Handling WorkerErrorEvent` | 1 |
| `Restarting worker channel` | 1 |
| `Exceeded language worker restart retry count` | 1 |
| late `StartStream` | 1 |

Later affected workers showed the same pattern: one process start, one startup timeout, immediate retry-exceeded log, and then a late `StartStream` from the original process.

## Code pointers

### `WorkerChannel` turns missing `StartStream` into `WorkerErrorEvent`

File: `src/WebJobs.Script.Grpc/Channel/WorkerChannel.cs`

- `BeginInboundProcessing(...)` registers a one-message wait for `MsgType.StartStream` using `startStreamTimeout`.
- `GrpcWorkerChannel.StartWorkerProcessAsync(...)` passes `WorkerConfig.CountOptions.ProcessStartupTimeout`.
- `WorkerProcessCountOptions.ProcessStartupTimeout` defaults to 60 seconds.
- On timeout, `HandleWorkerStartStreamError(...)` logs `Starting worker process failed` and publishes `WorkerErrorEvent`.

Relevant flow:

```csharp
protected void BeginInboundProcessing(TimeSpan startStreamTimeout)
{
RegisterCallbackForNextGrpcMessage(
MsgType.StartStream, startStreamTimeout, count: 1,
SendWorkerInitRequest, HandleWorkerStartStreamError);
_ = ProcessInbound();
}

internal void HandleWorkerStartStreamError(Exception exc)
{
_workerChannelLogger.LogError(exc, "Starting worker process failed");
PublishWorkerErrorEvent(exc);
}
```

### `WorkerFunctionMetadataProvider` starts a webhost channel before dispatcher initialization

File: `src/WebJobs.Script.Grpc/WorkerFunctionMetadataProvider.cs`

During worker indexing, if no channels exist and the JobHost is still starting, metadata provider initializes a webhost channel:

```csharp
if (channels?.Any() != true)
{
if (IsJobHostStarting())
{
_logger.LogDebug("JobHost is starting with state '{State}'. Initializing worker channel.", _scriptHostManager.State);
await _channelManager.InitializeChannelAsync(workerConfigs, _workerRuntime);
}
...
}
```

This is the path observed in production.

### `RpcFunctionInvocationDispatcher` subscribes to worker errors before its threshold is initialized

File: `src/WebJobs.Script.Grpc/Rpc/FunctionRegistration/RpcFunctionInvocationDispatcher.cs`

The dispatcher subscribes to `WorkerErrorEvent` in its constructor:

```csharp
_workerErrorSubscription = _eventManager.OfType().Subscribe(WorkerError);
```

But `ErrorEventsThreshold` is not assigned until `InitializeAsync(...)` gets function metadata:

```csharp
ErrorEventsThreshold = 3 * await _maxProcessCount.Value;
```

During the observed metadata-indexing timeout, the dispatcher has not yet logged `Worker process started and initialized.`, and the retry threshold appears to still be its default value `0`.

### Retry check immediately fails when threshold is 0

File: `src/WebJobs.Script.Grpc/Rpc/FunctionRegistration/RpcFunctionInvocationDispatcher.cs`

```csharp
private async Task StartWorkerChannel(string runtime)
{
...

if (_languageWorkerErrors.Count < ErrorEventsThreshold)
{
...
await InitializeJobhostLanguageWorkerChannelAsync(_languageWorkerErrors.Count, _workerRuntime);
...
}
else if (!_jobHostLanguageWorkerChannelManager.GetChannels().Any())
{
_hostMetrics.AppFailure();
_logger.LogError("Exceeded language worker restart retry count for runtime:{runtime}. Shutting down and proactively recycling the Functions Host to recover", runtime);
_applicationLifetime.StopApplication();
}
}
```

`WorkerError(...)` calls `AddOrUpdateErrorBucket(...)` before `StartWorkerChannel(...)`, so the first error makes `_languageWorkerErrors.Count == 1`. If `ErrorEventsThreshold == 0`, `1 < 0` is false and the host immediately goes to the `Exceeded language worker restart retry count` branch.

## Suspected root cause

The retry code assumes `ErrorEventsThreshold` has already been initialized by `RpcFunctionInvocationDispatcher.InitializeAsync(...)`. That assumption is false for worker-indexing startup failures, because the webhost metadata channel may start before the dispatcher receives function metadata and initializes its retry threshold.

There may also be a phase mismatch: `StartWorkerChannel(...)` retries by calling `InitializeJobhostLanguageWorkerChannelAsync(...)`, but the failed channel in this scenario is a webhost metadata-indexing channel. At metadata-indexing time `_functions` may not yet be populated, so starting a jobhost invocation channel may not be the correct retry action for this failure phase.

## Suggested fix direction

Potential approaches:

1. Initialize `ErrorEventsThreshold` earlier, e.g. in the dispatcher constructor or lazily inside `WorkerError(...)` / `StartWorkerChannel(...)`, so it is never left at `0` when handling `WorkerErrorEvent`.
2. Separate webhost metadata-channel retry handling from jobhost invocation-channel retry handling.
3. When the errored worker belongs to `WebHostRpcWorkerChannelManager`, retry `InitializeChannelAsync(...)` through the webhost channel manager rather than `InitializeJobhostLanguageWorkerChannelAsync(...)`.
4. Avoid logging `Restarting worker channel` before the threshold check, or add a clearer log when restart is skipped because the threshold has already been exceeded.

## Suggested tests

Add a test that models this exact sequence:

1. Construct `RpcFunctionInvocationDispatcher`, which subscribes to `WorkerErrorEvent`.
2. Do not call `InitializeAsync(...)`, or otherwise leave `ErrorEventsThreshold` in its pre-initialized state.
3. Start a webhost language worker channel for metadata indexing.
4. Simulate `ProcessStartupTimeout` before `StartStream`.
5. Assert the first timeout does not immediately call `StopApplication()` / log retry exceeded.
6. Assert a real retry is attempted for the metadata worker channel.

Also add a test where `ErrorEventsThreshold` is initialized but the failed channel is a webhost metadata channel, to verify the retry targets the correct manager/channel type.

## Impact

Under worker startup pressure or noisy-neighbor conditions, a .NET isolated worker may start successfully but send `StartStream` slightly after the 60s timeout. If this happens during worker indexing, the host can immediately recycle after the first timeout instead of retrying. This can leave the app unhealthy and amplify a transient slow startup into an outage.

In the observed production logs, normal startup was usually fast (~7-15s), but during a burst several starts took 66-109s. The late `StartStream` arrived shortly after timeout, but the host had already treated the worker as failed and exhausted retries.

Contributor guide

Open the contributing guide

Research direction

Start with src/WebJobs.Script.Grpc/Channel/WorkerChannel.cs and trace WorkerErrorEvent into RpcFunctionInvocationDispatcher in src/WebJobs.Script.Grpc/Rpc/FunctionRegistration/RpcFunctionInvocationDispatcher.cs. Compare the metadata-indexing path in WorkerFunctionMetadataProvider.cs with dispatcher initialization, then add the suggested tests for an uninitialized threshold and a webhost metadata-channel timeout. Done means the first timeout does not immediately stop the host and the correct retry path is exercised.

Written by the indexing model from the issue text.

Assessment

Tech stack
csharp
Domain
backend
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Quiet
Clarity
Mostly clear
Newbie friendliness
55/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.