From b1eedceacf6dca582e41e7fde0ef76699d725950 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 10 Nov 2026 07:36:11 -0500 Subject: [PATCH] =?UTF-8?q?docs(scripting):=20=C2=A712.4=20=E2=80=94=20Sha?= =?UTF-8?q?dow=20mode=20as=20built,=20its=20tests,=20and=20the=20docker-de?= =?UTF-8?q?v=20drill=20with=20alarms=20(lmxopcua#780=20P2)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Shadow on central-1/2 with all three seams: zero mismatches on ordinary VTs / Calc / alarms, counted mismatches on exactly the divergent (value) and decimal (unsupported_type) scripts, kill -9 of the shadow workers left every published value Good. OutOfProcess with ScriptedAlarm listed: alarms raise and clear, a runaway predicate is killed twice and quarantined (BadInternalError) with its siblings Active and Good, kill -9 under an in-flight predicate freezes it Active + BadResourceUnavailable and it re-evaluates in isolation. Answers A-7 (Modbus UInt16 boxes as ushort) and A-8 (a decimal VT publishes BadNotSupported in process). Rig restored to revision e221b179. Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV --- ...-09-out-of-process-script-runner-design.md | 95 +++++++++++++++++++ 1 file changed, 95 insertions(+) diff --git a/docs/plans/2026-11-09-out-of-process-script-runner-design.md b/docs/plans/2026-11-09-out-of-process-script-runner-design.md index 595df57b..d1938e85 100644 --- a/docs/plans/2026-11-09-out-of-process-script-runner-design.md +++ b/docs/plans/2026-11-09-out-of-process-script-runner-design.md @@ -707,6 +707,8 @@ per-shard state, restarts in the last hour and the quarantine list. Quarantines - Shadow doubles script CPU and still carries the in-process risk, so it is a time-boxed diagnostic (for example 1 week on QA), not a mode to run in production. - Exit criterion: zero unexplained mismatches. This is where [A-7] / [A-8] get answered. + - **Landed in lmxopcua#780 (P2 slice, record in §12.4):** `ShadowScriptRunner`, all three seams, bounded and + drop-counted, readiness untouched; docker-dev drill with alarms. The QA shadow week is still to run. 4. **P3, flip on QA, then the other tiers.** - Set `Scripting:Runner=OutOfProcess` per node, seam subset first (Calculation, then VT, then alarms; alarms last because of the 250 ms budget). @@ -1098,6 +1100,99 @@ other work on the box, 10 s phases):** - kill latency: 9–19 ms; - warm-cache restart of 1,000 scripts: 1.8 s. +### 12.4 P2 record: Shadow mode, and the docker-dev drill with alarms (2026-11-10) + +**What `Scripting:Runner=Shadow` does (as built).** +- The seams selected by `Scripting:Runner:Seams` (same rule as OutOfProcess: unset = VirtualTag + Calculation, + `ScriptedAlarm` only when listed) receive a `ShadowScriptRunner` (`Core.Scripting`) as their runner. They recognise it + as an `IScriptShadow` and keep their **in-process path byte for byte**: no VT coalescer, the one-at-a-time Calc pump, + the in-process alarm engine. After each compiled evaluation they call `Mirror(invocation, publishedOutcome)`. The + passthrough fast path and host-lifecycle failures (evaluator disposed, shutdown cancel) are not mirrored. +- `Mirror` copies the inputs (the alarm engine reuses its read cache), drops the script logger (the in-process run + already wrote its lines) and queues the shadow run on the pool. It never blocks and never throws. +- **Comparison:** value (structural for arrays), exact CLR type, status, failure class (`compile`; `budget` = timed + out / killed / refused / quarantined, which the two runners reach by different routes for the same runaway; `threw` + with its message; `unsupported_type`). A shadow outcome that is the runner's fault (`Unavailable`, worker busy) is + not compared (`shadow_unavailable`). ★11: a value the protocol cannot carry is a mismatch with reason + `unsupported_type`. +- **Bounded:** `Scripting:Shadow:MaxInFlight` (256) outstanding and one per script; the rest are dropped and counted + (`behind` | `key_busy`). One per script also keeps the out-of-process single-flight rule from refusing a shadow run + and reporting a false mismatch. +- **Observability:** `otopcua.script.shadow.compared{kind, result}`, `.mismatch{kind, reason, script}`, `.dropped{kind, + reason}`, `.inflight`. One Warning per script and reason, `Script shadow mismatch: () — published + …; shadow …`, re-armed at the seam's deploy boundary and capped at `Scripting:Shadow:MismatchLogsPerMinute` (20). +- **Readiness:** `ScriptRunnerSelection.Status()` is null under Shadow; the `script-runner` entry is always Healthy and + carries the shadow pool's state and the counters as data. The shadow pool's kill/quarantine lines go to the host log + with `ScriptRunnerRole=Shadow` (the console template does not render that property), never to the script log. +- Deviation from the §12 sketch ("mismatching keys are logged once each"): once per key **and reason**, plus the + per-minute cap. + +**Tests** (all mutation-checked; 16 mutants, all red after one survivor got an assertion): +- `ShadowScriptRunnerTests` (Core.Scripting, fakes): the comparison table; a divergent script counted per script in the + metric with one diff-summary line; the rate limit and suppressed-count note; reset re-arming; a shadow runner that + hangs, blocks its caller or throws never reaches the caller and is never a mismatch; MaxInFlight drop accounting; + inputs copied before `Mirror` returns. +- `ShadowModeTests` (real worker): eleven scripts over short / double / string / arrays / DateTime / bool / status / + a throw publish exactly what InProcess publishes and match; a deliberately divergent script (it reads + `AppContext.BaseDirectory`, so it answers differently in the worker) and a `decimal` result are counted against + exactly those two scripts (`value`, `unsupported_type`). A runaway that only runs away in the worker is killed twice + and quarantined **there** while every published value stays the in-process one, no published evaluation waits more + than 250 ms, and its sibling on the killed shard (a victim, not compared) has no mismatch. Alarms: the emission + sequence equals an in-process engine's across a `kill -9` of the shadow worker, and no shadow failure annotates a + condition. +- Host: selection (Shadow hands out the shadow, `Status()` null), binding/clamps, the health matrix (Healthy whatever + the shadow pool's state), the VT seam's mirror. +- Suites (macOS, Release, 0 warnings, `AKKA_TEST_TIMEFACTOR=3`): Core.Scripting 255/1 skip, ScriptedAlarms 109, + VirtualTags 16, Calculation 84, ScriptWorker 160/4 skip, Host 275, Runtime 1002/3 skip, OpcUaServer.IntegrationTests + 133. windev (Windows VM, scratch dir under `C:\build`): ScriptWorker suite 160 passed / 4 skipped, 0 warnings. The first + windev run caught a test bug (a `DateTime` seconds argument past 59 once the slower VM looped longer), fixed before the commit. +- Found while writing them: scripts can reach `System.AppContext` (`SetSwitch` / `SetData` / `GetData`) → + lmxopcua#792. + +**docker-dev drill** (image `otopcua-host:w34-shadow` built from this branch; `central-1`/`central-2` only; drill rows +`w34-*` inserted by SQL: VTs `w34mul` (HR5×3), `w34raw` (`var v = …HR5.Value; return v;` — compiled, returns the boxed +`ushort`), `w34div` (divergent), `w34dec` (`* 1.5m`), Calc `W34Calc` (HR5+1000), alarms `w34-al-hi` (HR5>50), +`w34-al-slow` (1.5 s spin, then HR5>50), `w34-al-run` (`while(true)` when HR5 == 77). HR5 driven by Modbus writes to the +fixture.) + +(a) **Shadow, all three seams** (`docker-compose.script-runner-shadow.yml`): + +| Step | Observed (both nodes) | +|---|---| +| HR5 = 21 / 60 / 30 | `w34mul` 63 / 180 / 90, `w34raw` 21 / 60 / 30, `W34Calc` 1021 / 1060 / 1030, `HR5x2` 42 / 120 / 60, all Good; `w34-al-hi` and `w34-al-slow` Active at 60 and Inactive at 30 | +| Mismatch counters (leader) | `compared{virtual_tag,match}` 146, `{calculation,match}` 11, `{alarm,match}` 14; `mismatch{virtual_tag,value,w34-vt-div}` 5 and `{virtual_tag,unsupported_type,w34-vt-dec}` 4 — **nothing else**. `dropped{key_busy}` 5 (startup burst) | +| Log | exactly two Warnings per node: `w34-vt-div (value) — published Ok Int32 1; shadow Ok Int32 2` and `w34-vt-dec (unsupported_type) — published Ok Decimal 7.5; shadow Failed [unsupported_type] … System.Decimal` | +| `kill -9` both shadow workers on the leader, then HR5 = 61 | Published values all correct and Good (183 / 61 / 1061 / 122); workers restarted within ms; `/health/ready` 200, `script-runner` Healthy | + +- **[A-7] answered for Modbus:** a UInt16 register arrives boxed as `ushort` and crosses the boundary unchanged (`w34raw` + matched on every evaluation). +- **[A-8] answered:** in process, a VT that returns a `decimal` publishes **`BadNotSupported`** (`0x803D0000`) with a null + value: the sink rejects it. Out of process it would publish `BadInternalError` "unsupported type". Either way it is Bad, + so the ★11 behaviour change is only the status code. + +(b) **OutOfProcess with `ScriptedAlarm` listed** (`docker-compose.script-runner.yml` + `Seams__2=ScriptedAlarm`): + +| Step | Observed (both nodes) | +|---|---| +| HR5 = 60, then 30 | `w34-al-hi` / `w34-al-slow` Active, then Inactive, Quality Good; `otopcua_script_ipc_roundtrip{kind="alarm"}` counting, so the predicates ran in the worker | +| HR5 = 77 (runaway), 76, 77 | `exceeded its hard deadline (4000 ms); killing ScriptWorker[0]` twice, then `quarantined: "it exceeded its hard deadline and its worker was killed (2 time(s) in the last hour)…"`. `w34-al-run` stays Inactive with Quality **BadInternalError**; `w34-al-hi` and `w34-al-slow` (same shard) stay Active and Good throughout | +| HR5 = 30, `kill -9` the shard-0 worker 0.6 s later, during `w34-al-slow`'s 1.5 s spin | `ScriptWorker[0] ended (Crash) with no deadline crossed; 1 script(s) in flight move to the isolation worker: 3:w34-al-slow`. Read at once: `w34-al-slow` **Active, Quality BadResourceUnavailable** (`0x80040000`): frozen, not cleared. By the next read, 19 s later, it is Inactive and Good, re-evaluated in the isolation worker with no further input change. `w34-al-hi` cleared normally; `w34-al-run` stays BadInternalError (quarantined) | +| `/health/ready` | 200, `script-runner` Healthy ("ready") after the restarts | + +(The kill loop stopped after one worker per node because its own shell matched the pattern; the killed worker was the +one running the in-flight predicate, which is what the step needed.) + +**Rig state afterwards.** +- `w34-*` rows deleted (Script 3, VirtualTag 1, ScriptedAlarm 1, Tag 55, as before), HR5 = 5, redeployed: revision + `e221b179…`, identical to the pre-drill deployment. +- `central-1`/`central-2` recreated from the base compose file in the same compose project: image `otopcua-host:dev` + (`24f9d7287ed2`, never re-tagged), no `Scripting__*` env, compose config hash equal to the base file's. The secret + stores live on the `otopcua-localdb-central-*` volumes since an earlier change, so they **survived** the recreates: + central-1's store is byte-identical; central-2's main file differs only by a WAL checkpoint (same size). Both log + `Mesh PSK secret ot-mesh-psk-* … is absent` at startup — central-1 with an unchanged store logs it too, so that is + the state the rig was already in (most likely from the earlier drill's store loss), not something this drill did. +- The drill image `otopcua-host:w34-shadow` was removed afterwards. The site nodes, sql and traefik were not touched. + --- ## 13. Test plan