From 850c5405d04cb122ca822e37acc1d6243b78f908 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 9 Nov 2026 21:20:39 -0500 Subject: [PATCH] fix(scripting): name the script on the mirrored quarantine line; keep BadInternalError (lmxopcua#784) (a) ScriptRunGuard logs its quarantine Error through the seam's script root logger, which carries no ScriptName, so ScriptLogCompanionSink mirrored it to the main log as "[Script] unknown emitted Error ..." and rate-limited every quarantine on the node under one shared "unknown" key. The guard now binds the script instance key as ScriptName (ForContext) on the quarantine Error and the subscriber-threw Warning, so the mirror names the script and limits each one separately. Test drives two real quarantines through the companion sink with a 1-per-window limiter: both mirrored, each named, none "unknown". Mutation- checked: dropping the ForContext fails it. (b) Evaluated a quarantine-specific OPC UA status (BadOutOfService) and kept BadInternalError: it is the documented code for any script-attributable fault on virtual tags, Calculation tags and scripted-alarm quality (and the out-of-process runner design keeps it), BadOutOfService reads as a deliberately disabled point, a new code is a ScadaBridge-visible contract change, and the once-per-Good->Bad dedup means a timeout-driven quarantine would rarely show a different code anyway. Documented in docs/VirtualTags.md ("Quarantine: what a client sees"), with pointers from Calculation.md, ScriptedAlarms.md and the OpcUaStatus.BadInternalError doc comment, plus where a quarantine IS visible. Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV --- docs/ScriptedAlarms.md | 2 + docs/VirtualTags.md | 26 +++++++++++ docs/drivers/Calculation.md | 4 ++ docs/reviews/2026-10-21/gates.md | 5 +++ .../OpcUa/OpcUaStatus.cs | 3 +- .../ScriptRunGuard.cs | 10 ++++- .../ScriptRunGuardTests.cs | 43 +++++++++++++++++++ 7 files changed, 90 insertions(+), 3 deletions(-) diff --git a/docs/ScriptedAlarms.md b/docs/ScriptedAlarms.md index 171a6f45..f538d72f 100644 --- a/docs/ScriptedAlarms.md +++ b/docs/ScriptedAlarms.md @@ -63,6 +63,8 @@ Evaluation cadence: If a predicate throws or times out, the engine logs the failure and leaves the prior `ActiveState` intact — it does not synthesise a clear. Operators investigating a broken predicate should never see a phantom clear preceding the error. +A predicate that times out, is refused behind its own still-running previous run, or is **quarantined** by `ScriptRunGuard` also freezes the condition and annotates it with `BadInternalError` quality, the same code virtual tags and Calculation tags use for a script fault. There is no quarantine-specific status code; the reasoning, and where a quarantine is visible instead (log line naming the script, `otopcua.script.quarantined`, `/script-log`), is in [VirtualTags.md](VirtualTags.md) §"Quarantine: what a client sees". + ### Dirty-set coalescing Every upstream push used to spawn its **own** fire-and-forget re-evaluation, each allocating a fresh diff --git a/docs/VirtualTags.md b/docs/VirtualTags.md index c4262df3..851977d1 100644 --- a/docs/VirtualTags.md +++ b/docs/VirtualTags.md @@ -41,6 +41,32 @@ The sandbox cannot pre-empt a script. **Memory:** each run's own-thread allocati `System.Threading.Tasks` is denied (Core.Scripting-003), which prevents `Task.Run` / `Parallel` fan-out that would spawn background work outliving the timeout. + +#### Quarantine: what a client sees (status code) + +A quarantined script's output reads **`BadInternalError`** on OPC UA, the same code as a script that +threw, timed out or was refused. This is deliberate (lmxopcua#784 evaluated a more specific code such as +`BadOutOfService` and kept `BadInternalError`): + +- **It is the documented contract for every script seam.** `BadInternalError` means "this tag's own script + failed" for virtual tags, Calculation tags (`docs/drivers/Calculation.md` §Error semantics) and the + scripted-alarm quality annotation, and the out-of-process runner design + (`docs/plans/2026-11-09-out-of-process-script-runner-design.md` §Status code) keeps it for every + script-attributable fault. Quarantine is such a fault: the script ran too long, got stuck, or allocated past + its budget. ScadaBridge consumes these codes, so a new one is a cross-repo contract change, not a local fix. +- **`BadOutOfService` says the wrong thing.** In Part 8 / classic DA usage it marks a point that was + deliberately taken out of service. A quarantine is automatic and means "fix this script"; an operator who + reads `BadOutOfService` looks for whoever disabled the point. +- **It would rarely change on the wire anyway.** The seams publish Bad once per Good→Bad transition. A + timeout-driven quarantine follows a timeout that already published `BadInternalError`, so a distinct code + would also need the dedup reworked to re-publish on the quarantine transition. + +The quarantine is identified elsewhere, not by the status code: one Error per quarantine in `scripts-*.log`, +mirrored to the main log as `[Script] "" emitted Error: Script "" quarantined: …` (named and +rate-limited per script), the `otopcua.script.quarantined` counter tagged `reason` = `timeouts` | `stuck` | +`allocation`, the `"script quarantined: …"` reason on the `/script-log` entry, and the evaluators' +`QuarantinedScripts`. A quarantine lifts on a source change or a redeploy. + ### Compile cache (`CompiledScriptCache`) `ConcurrentDictionary>>` keyed on `SHA-256(UTF8(source))` rendered to hex. `Lazy` with `ExecutionAndPublication` mode means two threads racing a miss compile exactly once. Failed compiles evict the entry (via the `TryRemove(KeyValuePair<,>)` overload so a concurrently re-added retry entry is not collateral damage — Core.Scripting-006) so a corrected retry can succeed (used during Admin UI authoring). No capacity bound — scripts are operator-authored and bounded by the config DB. Whitespace changes miss the cache on purpose. `Clear()` is called on config-publish. diff --git a/docs/drivers/Calculation.md b/docs/drivers/Calculation.md index db7f6f7f..1aebf19d 100644 --- a/docs/drivers/Calculation.md +++ b/docs/drivers/Calculation.md @@ -134,6 +134,10 @@ publishes: A historized Bad records `BadInternalError`. +A **quarantined** calc-tag script (`ScriptRunGuard`: repeated timeouts, a stuck run or an allocation breach) +also reads `BadInternalError`. Why no quarantine-specific code, and where the quarantine is visible instead: +`docs/VirtualTags.md` §"Quarantine: what a client sees". + ## Config ```json diff --git a/docs/reviews/2026-10-21/gates.md b/docs/reviews/2026-10-21/gates.md index 3276bba2..6bce423f 100644 --- a/docs/reviews/2026-10-21/gates.md +++ b/docs/reviews/2026-10-21/gates.md @@ -211,8 +211,13 @@ hold. `ScriptLogCompanionSink` as `WRN [Script] unknown emitted Error: Script "gateE-vt-spin" quarantined: …`. The guard's logger carries no `ScriptName`/`ScriptId` property, so the mirror labels it `unknown`, and it is rate-limited under that shared key. `scripts-*.log` has the correct `[ERR]` line. + **Resolved (lmxopcua#784):** the guard binds the script key as `ScriptName`, so the mirror names the script + and rate-limits each one separately. 6. **The quarantine shows as `BadInternalError` on OPC UA.** A client sees no quarantine-specific status. The reason is only in the logs and metrics. + **Decided (lmxopcua#784): kept `BadInternalError`**, the documented code for any script-attributable fault + on all three seams; `BadOutOfService` would read as a deliberately disabled point and would be a + ScadaBridge-visible contract change. Rationale: `docs/VirtualTags.md` §"Quarantine: what a client sees". ### Rig state left behind diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Commons/OpcUa/OpcUaStatus.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Commons/OpcUa/OpcUaStatus.cs index 5e7352b6..ed65b70c 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Commons/OpcUa/OpcUaStatus.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Commons/OpcUa/OpcUaStatus.cs @@ -43,7 +43,8 @@ public static class OpcUaStatus public const uint BadNoCommunication = 0x80310000; /// An internal failure produced no usable value — the virtual-tag path's code for a script - /// that threw or timed out. + /// that threw, timed out, was refused or was quarantined (kept for quarantine on purpose, lmxopcua#784: + /// see docs/VirtualTags.md §"Quarantine: what a client sees"). public const uint BadInternalError = 0x80020000; /// Part 4 severity bucket of : the top two bits. diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs index 7efa4026..27673028 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs @@ -358,11 +358,17 @@ public sealed class ScriptRunGuard QuarantinedCounter.Add(1, new KeyValuePair("script", key), new KeyValuePair("reason", metricReason)); - _logger.Error("Script {ScriptKey} quarantined: {Reason}", key, why); + // lmxopcua#784: bind the script's identity onto the event. The guard's logger is the seam's script ROOT + // logger, which carries no ScriptName, so ScriptLogCompanionSink mirrored this line into the main log as + // "[Script] unknown emitted Error ..." and rate-limited every quarantine on the node under one shared + // "unknown" key. The instance key (virtual-tag id, calc-tag RawPath, alarm id) is the identity the guard + // has, so the mirror now names the script and rate-limits each one separately. + var scoped = _logger.ForContext(ScriptLoggerFactory.ScriptNameProperty, key); + scoped.Error("Script {ScriptKey} quarantined: {Reason}", key, why); try { Quarantined?.Invoke(this, new ScriptQuarantinedEventArgs(key, reason)); } catch (Exception ex) { - _logger.Warning(ex, "ScriptRunGuard Quarantined subscriber threw for {ScriptKey}", key); + scoped.Warning(ex, "ScriptRunGuard Quarantined subscriber threw for {ScriptKey}", key); } } diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs index b4efe8af..ec526742 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs @@ -1,3 +1,6 @@ +using Serilog; +using Serilog.Core; +using Serilog.Events; using Shouldly; using Xunit; using ZB.MOM.WW.OtOpcUa.Core.Scripting; @@ -325,6 +328,46 @@ public sealed class ScriptRunGuardTests (await Run(guard, "ok", FastScript, fast, ct: ct)).ShouldBe(42); } + /// + /// lmxopcua#784 — the quarantine Error reaches the main log through . + /// The guard's logger is a seam's script root logger, which carries no ScriptName, so the mirror read + /// "[Script] unknown emitted Error ..." and every quarantine on the node shared one "unknown" rate-limit + /// key. The guard now binds the script instance key: the mirror names each script, and two scripts are + /// rate-limited apart (with a budget of 1 per window, the second quarantine is still mirrored). + /// + [Fact] + public async Task The_quarantine_line_mirrored_to_the_main_log_names_the_script_and_is_rate_limited_per_script() + { + var mainSink = new CapturingSink(); + var mainLogger = new LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(mainSink).CreateLogger(); + var scriptRoot = new LoggerConfiguration() + .MinimumLevel.Verbose() + .WriteTo.Sink(new ScriptLogCompanionSink(mainLogger, limiter: new ScriptLogRateLimiter(1, TimeSpan.FromMinutes(5)))) + .CreateLogger(); + var guard = new ScriptRunGuard(new ScriptingOptions { QuarantineAfterConsecutiveTimeouts = 1 }, scriptRoot); + using var spin = Compile(SpinScript); + var ct = TestContext.Current.CancellationToken; + + await Should.ThrowAsync(() => Run(guard, "vt-spin-a", SpinScript, spin, ShortTimeout, ct)); + await Should.ThrowAsync(() => Run(guard, "vt-spin-b", SpinScript, spin, ShortTimeout, ct)); + + var mirrored = mainSink.Events.Select(e => e.RenderMessage()).ToList(); + mirrored.Count.ShouldBe(2, string.Join(" | ", mirrored)); + mirrored.ShouldAllBe(m => !m.Contains("unknown")); + mirrored.ShouldContain(m => m.Contains("vt-spin-a") && m.StartsWith("[Script] \"vt-spin-a\" emitted Error")); + mirrored.ShouldContain(m => m.Contains("vt-spin-b") && m.StartsWith("[Script] \"vt-spin-b\" emitted Error")); + } + + private sealed class CapturingSink : ILogEventSink + { + public List Events { get; } = []; + + public void Emit(LogEvent logEvent) + { + lock (Events) Events.Add(logEvent); + } + } + [Fact] public async Task A_disabled_allocation_budget_never_quarantines() {