fix(scripting): name the script on the mirrored quarantine line; keep BadInternalError (lmxopcua#784)
v2-ci / unit-tests (push) Has been cancelled
v2-ci / unit-tests (push) Has been cancelled
(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
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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] "<key>" emitted Error: Script "<key>" 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<TContext, TResult>`)
|
||||
|
||||
`ConcurrentDictionary<string, Lazy<ScriptEvaluator<...>>>` keyed on `SHA-256(UTF8(source))` rendered to hex. `Lazy<T>` 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.
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
|
||||
@@ -43,7 +43,8 @@ public static class OpcUaStatus
|
||||
public const uint BadNoCommunication = 0x80310000;
|
||||
|
||||
/// <summary>An internal failure produced no usable value — the virtual-tag path's code for a script
|
||||
/// that threw or timed out.</summary>
|
||||
/// 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").</summary>
|
||||
public const uint BadInternalError = 0x80020000;
|
||||
|
||||
/// <summary>Part 4 severity bucket of <paramref name="statusCode"/>: the top two bits.</summary>
|
||||
|
||||
@@ -358,11 +358,17 @@ public sealed class ScriptRunGuard
|
||||
QuarantinedCounter.Add(1,
|
||||
new KeyValuePair<string, object?>("script", key),
|
||||
new KeyValuePair<string, object?>("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);
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -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);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// lmxopcua#784 — the quarantine Error reaches the main log through <see cref="ScriptLogCompanionSink"/>.
|
||||
/// 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).
|
||||
/// </summary>
|
||||
[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<ScriptQuarantinedException>(() => Run(guard, "vt-spin-a", SpinScript, spin, ShortTimeout, ct));
|
||||
await Should.ThrowAsync<ScriptQuarantinedException>(() => 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<LogEvent> Events { get; } = [];
|
||||
|
||||
public void Emit(LogEvent logEvent)
|
||||
{
|
||||
lock (Events) Events.Add(logEvent);
|
||||
}
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task A_disabled_allocation_budget_never_quarantines()
|
||||
{
|
||||
|
||||
Reference in New Issue
Block a user