Azure / Azure/azure-functions-nodejs-worker

Specialization race: double startApp() with stale require cache leaves worker on default v3 model with all functions unloadable

Open
#838 1 comment 0 reactions 0 assignees View on GitHub
Dominant language
TypeScript
Stars
110
Forks
51
Avg merge
1d 1h
Merged PRs (30d)
2

Description

## Summary

On an Elastic Premium placeholder specialization, a Node.js worker ran full entry-point registration **twice** in the same process (once from `WorkerInitRequest`, once from `FunctionEnvironmentReloadRequest`). Because Node's `require` cache is not invalidated between the two passes, the second pass is effectively a no-op — while `resetApp()` has already reverted the programming model to the bundled default.

The worker ends up on the **legacy v3 model with zero registered functions**. Every `FunctionLoadRequest` then fails with:

```
The resolved entry point is not a function and cannot be invoked by the functions runtime.
```

The host still logged `Worker process started and initialized.`, started the Event Hub listener, and checkpointed every unprocessed event. The poisoned worker was **not recycled for ~62 minutes** — recovery only happened on the next platform drain. Roughly 460 Event Hub events were checkpointed without ever reaching user code.

This required three independent defects to line up, across three repos. Filing here because the primary defect is in this repo.

**Observed environment**

| Item | Value |
|---|---|
| Plan | Elastic Premium (placeholder specialization path) |
| Host | 4.1051.300.26316 |
| Node runtime | 20.20.2 |
| Node worker | 3.14.1 |
| App programming model | `@azure/functions` 4.12.0 |
| Model observed on bad worker | **4.12.0 and 3.5.0 on the same worker process** |
| Trigger | Event Hub, `EnableCheckpointing=true`, `BatchCheckpointFrequency=1` |

Internal tracking: ICM 21000001556804.

---

## Defect 1 (this repo) — double `startApp()` with a stale `require` cache

### Mechanism

| # | Location | What happens |
|---|---|---|
| 1 | [`src/coreApi/setProgrammingModel.ts#L16-L18`](https://github.com/Azure/azure-functions-nodejs-worker/blob/v3.x/src/coreApi/setProgrammingModel.ts#L16-L18) | The **first** model ever registered becomes `worker.defaultProgrammingModel`. On a placeholder worker that is the bundled legacy model — **3.5.0**. |
| 2 | [`src/eventHandlers/WorkerInitHandler.ts#L50-L54`](https://github.com/Azure/azure-functions-nodejs-worker/blob/v3.x/src/eventHandlers/WorkerInitHandler.ts#L50-L54) | Pass #1 runs `startApp()`. The app's own `@azure/functions` 4.12.0 calls `setProgrammingModel(4.12.0)` and registers its functions. |
| 3 | [`src/WorkerContext.ts#L57-L60`](https://github.com/Azure/azure-functions-nodejs-worker/blob/v3.x/src/WorkerContext.ts#L57-L60) | `resetApp()` builds a new `AppContext` and sets `programmingModel = defaultProgrammingModel` — silently reverting to **3.5.0**. |
| 4 | [`src/loadScriptFile.ts#L64`](https://github.com/Azure/azure-functions-nodejs-worker/blob/v3.x/src/loadScriptFile.ts#L64) | Pass #2 calls `require(entryPointFilePath)` — **cache hit**. Top-level `app.eventHub(...)` and `setProgrammingModel(4.12.0)` side effects never re-run. |
| 5 | [`src/eventHandlers/FunctionLoadHandler.ts#L36`](https://github.com/Azure/azure-functions-nodejs-worker/blob/v3.x/src/eventHandlers/FunctionLoadHandler.ts#L36) | `isUsingWorkerIndexing` is now false, so loading falls through to the legacy v3 loader. |
| 6 | [`src/LegacyFunctionLoader.ts#L68-L71`](https://github.com/Azure/azure-functions-nodejs-worker/blob/v3.x/src/LegacyFunctionLoader.ts#L68-L71) | The v4 module export is not a v3-style function, so it throws the error above. |

### Why the dual `modelVersion` is the smoking gun

`4.12.0` and `3.5.0` reported by a single worker process are the two `getWorkerMetadata()` snapshots: 4.12.0 in the `WorkerInitResponse` (after pass #1) and 3.5.0 in the `FunctionEnvironmentReloadResponse` (after `resetApp()` + a no-op pass #2). Healthy workers on the same app show exactly one registration pass and a single `modelVersion=4.12.0`.

That the error originates in `LegacyFunctionLoader` — the **v3** loader — independently confirms the worker had fallen back to the default model.

### Why the existing safety assumption does not hold

[`src/startApp.ts#L16-L22`](https://github.com/Azure/azure-functions-nodejs-worker/blob/v3.x/src/startApp.ts#L16-L22) states:

> The dummy app should never have actual startup code, so it should be safe to call `startApp` twice in this case

Telemetry shows pass #1 loaded the **real** application's entry point files, not a dummy. So the precondition that makes the double call safe was violated. Even setting that aside, "safe to call twice" is only true if the second call actually re-registers — and with a warm `require` cache it cannot.

### Requested change

1. **Invalidate the `require` cache** for the application subtree in `resetApp()` (or immediately before pass #2), so registration side effects genuinely re-execute. Alternatively, **skip entry-point loading during `WorkerInit` when in placeholder mode** and defer it entirely to the reload.
2. **Do not silently downgrade the programming model.** If a non-default model was active before the reload and pass #2 does not re-register one, fail loudly rather than falling back to v3 and producing a confusing entry-point error.
3. **Add an invariant/metric** for more than one distinct `modelVersion`, or more than the expected number of entry-point load events per file, within a single worker process.

### Defect 1b (amplifier, same repo) — entry-point glob does not exclude `node_modules`

[`src/startApp.ts#L64`](https://github.com/Azure/azure-functions-nodejs-worker/blob/v3.x/src/startApp.ts#L64):

```ts
const files = await globby(entryPointPattern, { cwd: functionAppDirectory });
```

There is no `node_modules` exclusion, so a broad `main` pattern pulls dependency files in as entry points. In this incident `node_modules/cookie/index.js` was loaded and logged as an entry point file.

**Requested change:** exclude `node_modules` from the entry-point glob (e.g. add `!**/node_modules/**`), and/or warn when a matched entry point resolves inside `node_modules`.

---

## Defect 2 — `Azure/azure-functions-host`: no worker health gate on load failure

Two independent gaps:

**(a)** In [`src/WebJobs.Script.Grpc/Channel/WorkerChannel.cs#L832-L861`](https://github.com/Azure/azure-functions-host/blob/dev/src/WebJobs.Script.Grpc/Channel/WorkerChannel.cs#L832-L861), `LoadResponse` caches the failure and then **unconditionally** wires up the invocation buffer anyway:

```csharp
// runs even when the load FAILED
var invokeBlock = new ActionBlock(async ctx => await SendInvocationRequest(ctx));
var disposableLink = _functionInputBuffers[loadResponse.FunctionId].LinkTo(invokeBlock);
```

**(b)** In [`src/WebJobs.Script.Grpc/Rpc/FunctionRegistration/RpcFunctionInvocationDispatcher.cs#L176-L188`](https://github.com/Azure/azure-functions-host/blob/dev/src/WebJobs.Script.Grpc/Rpc/FunctionRegistration/RpcFunctionInvocationDispatcher.cs#L176-L188), `SendFunctionLoadRequests` is fire-and-forget and `SetFunctionDispatcherStateToInitializedAndLog()` is called immediately after, never awaiting the responses. In the incident, the three load failures and the `Worker process started and initialized.` line are **1 ms apart**.

There is no aggregate check anywhere for "did every function fail to load?"

**Requested change**
1. Add an aggregate load-result gate: if all functions — or all trigger-bearing functions — fail to load, do **not** transition to `Initialized`, do **not** start trigger listeners, and **recycle** the worker channel / mark the instance unhealthy.
2. Qualify the `Worker process started and initialized.` message with loaded/failed counts. (The message text is pinned by the VS Code debugger attach, so extend rather than rename.)
3. Emit a high-severity event such as `FunctionsWorkerAllLoadsFailed` with AppName, HostInstanceId, WorkerId, RoleInstance.

---

## Defect 3 — `Azure/azure-sdk-for-net`: Event Hubs checkpoints events that never reached user code

In [`sdk/eventhub/Microsoft.Azure.WebJobs.Extensions.EventHubs/src/Listeners/EventHubListener.PartitionProcessor.cs`](https://github.com/Azure/azure-sdk-for-net/blob/main/sdk/eventhub/Microsoft.Azure.WebJobs.Extensions.EventHubs/src/Listeners/EventHubListener.PartitionProcessor.cs), the execution result is discarded (single dispatch ~L147, batch ~L261):

```csharp
await _executor.TryExecuteAsync(input, linkedCts.Token).ConfigureAwait(false);
```

and the checkpoint (~L234-L243) is gated only on cancellation tokens, never on the result. This is deliberate per the comment at ~L226-L230:

> we intentionally checkpoint the batch regardless of function success/failure. EventHub doesn't support any sort "poison event" model...

**That reasoning is sound for genuine user-code exceptions**, and should be preserved. The defect is that the code cannot distinguish:

- **user-code failure** — the function ran and threw; the user had their chance, from
- **host-side never-invoked** — the host short-circuits at [`WorkerChannel.cs#L880-L887`](https://github.com/Azure/azure-functions-host/blob/dev/src/WebJobs.Script.Grpc/Channel/WorkerChannel.cs#L880-L887) because the function failed to load, and the event **never reaches user code at all**.

Only the second case is silent data loss, and no `try`/`catch` in user code can mitigate it because user code never runs.

**Requested change:** capture the `FunctionResult` from `TryExecuteAsync` and suppress the checkpoint **only** when the failure is a host-side load/binding failure. Keep current behaviour for user-code exceptions to avoid a breaking change.

---

## Why this matters

Each defect alone is survivable. Combined they convert a rare, self-healing startup race into **silent, unrecoverable customer data loss**:

- The race produces a worker that can never serve traffic.
- The missing health gate keeps that worker in rotation and attaches Event Hub consumers to it.
- The checkpoint path then advances the offset past every event the worker could not process.

The failure is also close to invisible. `Function failed to load` is logged at **Verbose**, the host reports the worker as initialized, and in the incident only 12 of 462 failed invocations emitted a normal `Executed ... (Failed)` completion — so dashboards and the Failures blade did not reflect a total outage.

There is no customer-side mitigation for defect 2 or 3, and no customer-visible way to recycle a single poisoned worker.

---

## Suggested acceptance tests

- EP placeholder specialization soak with the Node v4 model and an Event Hub trigger: zero dual-registration workers over N specializations.
- Fault injection — force `FunctionLoad` failure for all functions: assert no trigger listener starts and no checkpoint advances.
- Fault injection — double entry registration / dual `modelVersion`: assert the worker is recycled.
- Regression test: `main` glob that would match inside `node_modules` does not load dependency files as entry points.
- Telemetry test: `FailedToLoad` count equal to `Executing` count is reflected as a full outage in metrics.

Contributor guide

No contributing guide indexed for this repository

Research direction

Start with src/startApp.ts, src/WorkerContext.ts, src/loadScriptFile.ts, and the WorkerInitHandler and FunctionLoadHandler paths to trace the two registration passes and model reset. Review the listed acceptance tests, especially the node_modules glob regression and dual modelVersion checks. Done means the requested startup safeguards and regression coverage prevent a poisoned worker from serving or silently checkpointing events.

Written by the indexing model from the issue text.

Assessment

Tech stack
node.js, typescript
Domain
backend
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Active
Clarity
Mostly clear
Newbie friendliness
30/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.