Script worker start failures log an Error with a stack trace on every backoff retry #788

New Issue

2026-11-10T00:47:22-05:00

dohertj2 commented

2026-11-10 00:47:22 -05:00

Found during the lmxopcua#780 docker-dev live drill (2026-11-10). The drill made the worker unlaunchable (its dll renamed) for about 3 minutes.

WorkerShard logs ScriptWorker[n] failed to start; scripts on it report runner unavailable until it does at Error, with the full InvalidOperationException stack trace, on every retry. There are three shards (0, 1, iso), and the retries cap at a 30 s backoff, so the noise never stops while the condition lasts: 28 Error+stack entries in the first two minutes on one node.

The crash-loop circuit already logs one Error when it opens (Script runner circuit OPEN: …) and one Information line when it closes. That pair is the operator signal.

Proposal. Log the first failed start of a down period at Error with the exception. Log later retries at Warning with no stack (or Debug), with a failure count. When the shard starts again, log one line covering the outage (started after N failed attempts over T). Pin it with a log-capture test in SupervisionTests.

Found during the lmxopcua#780 docker-dev live drill (2026-11-10). The drill made the worker unlaunchable (its dll renamed) for about 3 minutes. `WorkerShard` logs `ScriptWorker[n] failed to start; scripts on it report runner unavailable until it does` at **Error**, with the full `InvalidOperationException` stack trace, on **every** retry. There are three shards (0, 1, iso), and the retries cap at a 30 s backoff, so the noise never stops while the condition lasts: 28 Error+stack entries in the first two minutes on one node. The crash-loop circuit already logs one Error when it opens (`Script runner circuit OPEN: …`) and one Information line when it closes. That pair is the operator signal. **Proposal.** Log the first failed start of a down period at Error with the exception. Log later retries at Warning with no stack (or Debug), with a failure count. When the shard starts again, log one line covering the outage (`started after N failed attempts over T`). Pin it with a log-capture test in `SupervisionTests`.

dohertj2 added the type:followup priority:p3 labels 2026-11-10 00:47:22 -05:00

dohertj2 referenced this issue

2026-11-10 03:01:18 -05:00

Implement the out-of-process script runner (design #750) — code on master; QA shadow week (#793, #794) + P3 flip remain #780

dohertj2 referenced this issue from a commit

2026-11-10 04:33:21 -05:00

perf(scripting): cut out-of-process runner host CPU; compile timeout from compile start; quiet start-failure logs (lmxopcua#789, #790, #788)

dohertj2 commented

2026-11-10 04:34:04 -05:00

Fixed on master @ 8582ce91 (WorkerShard.StartCoreAsync). What one down period of a shard now logs:

The first failed start logs one Error with the exception and stack: failed to start; … (retrying with backoff).
Later retries log a Warning with no stack: still failing to start: {Attempts} failed attempt(s) over {Outage}; last error: {Error}. This is rate-limited to one per 60 s per shard; the other retries log at Debug.
When the shard starts again, it logs one Information line: started, pid N, after {Attempts} failed start attempt(s) over {Outage}.
The crash-loop circuit's own Error / Information pair is unchanged.

Test. A_shard_that_cannot_start_logs_one_error_then_concise_rate_limited_retries_then_its_recovery (theory) uses a launch that fails 3 times and then starts a real worker:

With a warning interval of 0: 1 Error (with exception), 2 Warnings with attempts 2 and 3 and no stack, and recovery Information naming 3 attempts.
With a 1 h interval: 1 Error, 0 Warnings, 2 Debug lines.

Mutation check. Logging every failure at Error with the exception turns both cases red. Closing.

**Fixed on `master` @ `8582ce91`** (`WorkerShard.StartCoreAsync`). What one down period of a shard now logs: - The **first** failed start logs one Error with the exception and stack: `failed to start; … (retrying with backoff)`. - Later retries log a **Warning with no stack**: `still failing to start: {Attempts} failed attempt(s) over {Outage}; last error: {Error}`. This is rate-limited to one per 60 s per shard; the other retries log at Debug. - When the shard starts again, it logs **one Information** line: `started, pid N, after {Attempts} failed start attempt(s) over {Outage}`. - The crash-loop circuit's own Error / Information pair is unchanged. **Test.** `A_shard_that_cannot_start_logs_one_error_then_concise_rate_limited_retries_then_its_recovery` (theory) uses a launch that fails 3 times and then starts a real worker: - With a warning interval of 0: 1 Error (with exception), 2 Warnings with attempts 2 and 3 and no stack, and recovery Information naming 3 attempts. - With a 1 h interval: 1 Error, 0 Warnings, 2 Debug lines. **Mutation check.** Logging every failure at Error with the exception turns both cases red. Closing.

dohertj2 closed this issue

2026-11-10 04:34:04 -05:00

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: dohertj2/lmxopcua#788