docs(scripting): §12.4 — Shadow mode as built, its tests, and the docker-dev drill with alarms (lmxopcua#780 P2)
v2-ci / unit-tests (push) Has been cancelled
v2-ci / unit-tests (push) Has been cancelled
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
This commit is contained in:
@@ -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: <kind> <key> (<reason>) — 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
|
||||
|
||||
Reference in New Issue
Block a user