diff --git a/docs/ScriptEditor.md b/docs/ScriptEditor.md index 5321aca8..eb6985e2 100644 --- a/docs/ScriptEditor.md +++ b/docs/ScriptEditor.md @@ -162,11 +162,54 @@ user's fault. `ForbiddenTypeAnalyzer.Analyze(compilation)` walks the wrapped syntax tree and resolves every referenced symbol against the sandbox deny-list (namespace prefixes `System.IO`, `System.Net`, `System.Diagnostics`, `System.Reflection`, -`System.Threading.Tasks`, etc., plus type-granular denials like -`System.Environment` and `System.Threading.Thread`). Each violation is mapped +`System.Threading` — the whole namespace, with only `CancellationToken`, +`Interlocked` and `Volatile` allowed back in — `System.Threading.Tasks`, +`System.Runtime.InteropServices`, `System.Runtime.Loader`, `Microsoft.Win32`; +type-granular denials `System.Environment`, `System.AppDomain`, `System.GC`, +`System.Activator`, `System.Runtime.CompilerServices.Unsafe` / +`RuntimeHelpers`; and member-granular denials on `System.Type`'s by-name +reflection entry points — `GetType(string)`, `GetMethod(s)`, `InvokeMember`, +and the `GetProperty`/`GetField`/`GetMember`/`GetConstructor`/`GetEvent` +families). The runtime publish gate uses the same analyzer, so a deny-list +change needs a `DiagnoseTests` case to keep editor ⇔ publish parity. Each violation is mapped via `tree.GetMappedLineSpan(span)` to user-source coordinates and emitted as an error marker with code `OTSCRIPT_FORBIDDEN`. +### Runtime safety (what happens after publish) + +The editor cannot catch a script that compiles cleanly but never returns or +allocates without bound, so every runtime seam (virtual tags, Calculation tags, +scripted-alarm predicates) runs scripts through the shared `ScriptRunGuard`: + +- **Timeout + one orphan.** A run that exceeds its budget is abandoned (it cannot + be pre-empted in-process) and the tag/alarm reads Bad. While that abandoned run + is still executing, every further trigger is **refused** — Bad + `"previous evaluation still running"`, counted on `otopcua.script.run_refused` — + so a `while(true)` costs one pool thread, not one per trigger. +- **Quarantine after 3 consecutive timeouts** (`Scripting:QuarantineAfterConsecutiveTimeouts`). + Only a timeout is a strike: a refusal neither adds to nor resets the streak, and + a run that returns (value or throw) resets it. A quarantined script is never + dispatched again; it reads Bad `"script quarantined: …"`, logs one Error and + increments `otopcua_script_quarantined`. +- **Stuck-orphan quarantine.** A never-returning script (`while(true)`) times out + once and is then only refused, so the timeout streak alone never reaches 3. + Instead, a refusal behind an orphan that has been running longer than + `Scripting:StuckOrphanQuarantineFactor` × the timeout (default 10 × — 20 s at the + 2 s default) quarantines immediately, through the same path (Error log, metric + `reason=stuck`, Bad). A short overrun (a young orphan) stays a plain refusal and + the script resumes once the orphan completes. +- **Allocation budget.** A single run allocating more than + `Scripting:MaxAllocBytesPerRun` (64 MB) is quarantined. This is sampled after the + run returns, so a run that OOMs the process first is not stopped — that needs an + out-of-process runner. +- **Lifting.** A quarantine lifts when the script source changes or on redeploy, + never by itself. +- **Script-log rate limit.** The cluster-wide script-log fan-out admits 20 entries + per source per minute; the rest are counted and replaced by one "N suppressed" + summary. The summary is emitted on that source's **next** entry after the window + rolls, so a source that bursts and then goes quiet shows its summary only when + it logs again (the full stream is always in `scripts-*.log`). + ### 3. DependencyExtractor `DependencyExtractor.Extract(code).Rejections` enumerates every `ctx.GetTag` / diff --git a/docs/VirtualTags.md b/docs/VirtualTags.md index d58013ea..183fcef0 100644 --- a/docs/VirtualTags.md +++ b/docs/VirtualTags.md @@ -28,15 +28,15 @@ User scripts are compiled via `Microsoft.CodeAnalysis.CSharp` (regular compiler, `ScriptSandbox.Build` constructs the compile reference set in two parts. First, four pinned OtOpcUa assemblies are always included: `Core.Abstractions` (for `DataValueSnapshot` / `DriverDataType`), `Core.Scripting` (for `ScriptContext` + `Deadband`), `Serilog` (for `ILogger`), and the concrete context type's assembly. Second, the BCL subset is enumerated from the runtime's `TRUSTED_PLATFORM_ASSEMBLIES` list, restricted to filenames starting with `System.*` plus `netstandard.dll`, `mscorlib.dll`, and `Microsoft.Win32.Registry.dll` (the last needed so `ForbiddenTypeAnalyzer` can resolve and reject registry types). Pre-imported namespaces: `System`, `System.Linq`, `ZB.MOM.WW.OtOpcUa.Core.Abstractions`, `ZB.MOM.WW.OtOpcUa.Core.Scripting`. -`ForbiddenTypeAnalyzer.ForbiddenNamespacePrefixes` denies `System.IO`, `System.Net`, `System.Diagnostics`, `System.Reflection`, `System.Threading.Tasks`, `System.Runtime.InteropServices`, `System.Runtime.Loader`, and `Microsoft.Win32`. Matching is by prefix against the resolved symbol's containing namespace, so `System.Net` catches `System.Net.Http.HttpClient` and every subnamespace. `System.Threading.Tasks` is denied because scripts are synchronous predicates with no legitimate need to start background tasks — a `Task.Run` fan-out would outlive the per-evaluation timeout entirely (Core.Scripting-003). `System.Runtime.Loader` is denied to block `AssemblyLoadContext` / `AssemblyDependencyResolver` — arbitrary DLL loads into the host process (Core.Scripting-012). +`ForbiddenTypeAnalyzer.ForbiddenNamespacePrefixes` denies `System.IO`, `System.Net`, `System.Diagnostics`, `System.Reflection`, `System.Threading` (the whole namespace — `ForbiddenTypeAnalyzer.AllowedTypesInForbiddenNamespaces` lets only `CancellationToken`, `Interlocked` and `Volatile` back in), `System.Threading.Tasks`, `System.Runtime.InteropServices`, `System.Runtime.Loader`, and `Microsoft.Win32`. Matching is by prefix against the resolved symbol's containing namespace, so `System.Net` catches `System.Net.Http.HttpClient` and every subnamespace. `System.Threading.Tasks` is denied because scripts are synchronous predicates with no legitimate need to start background tasks — a `Task.Run` fan-out would outlive the per-evaluation timeout entirely (Core.Scripting-003). `System.Runtime.Loader` is denied to block `AssemblyLoadContext` / `AssemblyDependencyResolver` — arbitrary DLL loads into the host process (Core.Scripting-012). -`ForbiddenTypeAnalyzer.ForbiddenFullTypeNames` denies type-granularly: `System.Environment`, `System.AppDomain`, `System.GC`, `System.Activator`, `System.Threading.Thread`, `System.Threading.ThreadPool`, and `System.Threading.Timer`. These types require granular denial rather than namespace-prefix denial for different reasons: `Environment` / `AppDomain` / `GC` / `Activator` live directly in the `System` namespace (which is otherwise allowed for primitives), so a namespace-prefix rule cannot reach them without blocking `int` / `string` / `Math`; `Thread` / `ThreadPool` / `Timer` live in `System.Threading` (shared with allowed types like `CancellationToken` and `SemaphoreSlim`), so a prefix on `System.Threading` would block those too. `Environment.Exit` / `FailFast` terminate the host process outright (Core.Scripting-001); `Thread` and `ThreadPool` reintroduce background-fanout vectors that `System.Threading.Tasks` denial closed (Core.Scripting-010 / -012). +`ForbiddenTypeAnalyzer.ForbiddenFullTypeNames` denies type-granularly: `System.Environment`, `System.AppDomain`, `System.GC`, `System.Activator`, `System.Runtime.CompilerServices.Unsafe`, and `System.Runtime.CompilerServices.RuntimeHelpers`. These live in namespaces that are otherwise allowed — `System` (primitives, `Math`) and `System.Runtime.CompilerServices` (compile-time attributes such as `CallerMemberNameAttribute`) — so a namespace-prefix rule cannot reach them. `Environment.Exit` / `FailFast` terminate the host process outright (Core.Scripting-001); `Unsafe.As` bypasses the type system; `RuntimeHelpers.GetUninitializedObject` builds an instance of any type without a constructor. `Thread` / `ThreadPool` / `Timer` / `SemaphoreSlim` and the rest of `System.Threading` are now caught by the namespace prefix above instead of being listed one by one — a script is a synchronous expression with no use for background work or blocking primitives (Core.Scripting-010 / -012, review R05:10). `ForbiddenTypeAnalyzer.ForbiddenMembers` additionally denies `System.Type`'s by-name reflection entry points (`GetType(string)`, `GetMethod(s)`, `InvokeMember`, and the `GetProperty`/`GetField`/`GetMember`/`GetConstructor`/`GetEvent` families), which would otherwise reach a forbidden type without naming it syntactically. #### Known resource limits (accepted trade-offs) -The sandbox cannot prevent a script from **allocating unbounded memory**. A script calling `new byte[int.MaxValue]` repeatedly, or accumulating a large LINQ enumeration, can drive the server process to `OutOfMemoryException` before the 250 ms timeout fires. Script authoring is gated behind the Admin permission as the primary control; the test-harness preview (Stream F.4) allows operators to exercise a script before publishing. Out-of-process script execution is a v3 concern. +The sandbox cannot pre-empt a script. **Memory:** each run's own-thread allocation is sampled (`GC.GetAllocatedBytesForCurrentThread`) and a run over `Scripting:MaxAllocBytesPerRun` (default 64 MB) quarantines the script — but the sample is taken after the run returns, so a script that allocates fast enough (`new byte[int.MaxValue]` in a loop) can still OOM the process first. **CPU:** a tight loop keeps its pool thread after the timeout fires; `ScriptRunGuard` bounds that to one orphan per script by refusing further runs while it spins (Bad `"previous evaluation still running"`) and quarantines after three consecutive timeouts (a refusal is not a strike) — or immediately on a refusal behind an orphan that has run longer than `Scripting:StuckOrphanQuarantineFactor` (default 10) × the timeout, which is what quarantines a never-returning `while(true)`. Both are mitigations; pre-emptive CPU/memory limits need an out-of-process runner. Script authoring is gated behind the Admin permission as the primary control. See `docs/ScriptEditor.md` §"Runtime safety". -Similarly, **`System.Threading.Tasks` is now denied** (Core.Scripting-003), which prevents `Task.Run` / `Parallel` fan-out that would spawn background work outliving the timeout. However, a tight CPU-bound loop still runs on its thread-pool thread after `WaitAsync` returns — see the `TimedScriptEvaluator` remarks for detail. The orphaned thread is reclaimed when the Roslyn runtime eventually returns; in practice the operator fixes the script once the structured timeout warning appears in `scripts-*.log`. +`System.Threading.Tasks` is denied (Core.Scripting-003), which prevents `Task.Run` / `Parallel` fan-out that would spawn background work outliving the timeout. ### Compile cache (`CompiledScriptCache`) diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Configuration/Validation/DraftValidator.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Configuration/Validation/DraftValidator.cs index 04e08fe9..96a25da5 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Configuration/Validation/DraftValidator.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Configuration/Validation/DraftValidator.cs @@ -452,6 +452,58 @@ public static class DraftValidator "Calculation tags form a dependency cycle (members: " + string.Join(", ", cycle) + "); a calc→calc cycle is a live oscillation loop and must be broken before deploy", cycle.Count > 0 ? cycle[0] : null)); + + // Rule 3 — effective-trigger gate (R07:U5). A calc tag evaluates on a declared dependency + // changing (change-trigger: the literal ctx.GetTag paths) and/or on a timer. A change-triggered + // tag whose script has NO literal reads (`return ctx.Now.Hour;`, a dynamic-path read) and no timer + // never evaluates at all: it sits BadWaitingForInitialData forever while the driver reports + // Healthy, and nothing warned. Same for a tag that is neither change- nor timer-triggered. + foreach (var (t, _, scriptId) in calcTags) + { + var (changeTriggered, timerIntervalMs) = ParseTriggers(t.TagConfig); + if (timerIntervalMs is > 0) continue; + var source = scriptId is not null && scriptSourceById.TryGetValue(scriptId, out var s) ? s : null; + // An unresolved scriptId is already CalculationScriptMissing / CalculationScriptNotFound; with no + // source there are no reads to count, so a change-triggered tag would get a second, misleading + // "no literal ctx.GetTag read" error. (changeTriggered=false + no timer is source-independent.) + if (changeTriggered && source is null) continue; + var depCount = EquipmentScriptPaths.ExtractDependencyRefs(source).Count; + if (changeTriggered && depCount > 0) continue; + errors.Add(new("CalculationNoEffectiveTrigger", + changeTriggered + ? $"Calculation tag '{t.TagId}' is change-triggered but its script has no literal ctx.GetTag read, " + + "and it has no timerIntervalMs — nothing would ever evaluate it. Add a dependency read or a timer." + : $"Calculation tag '{t.TagId}' has changeTriggered=false and no timerIntervalMs — nothing would ever evaluate it. " + + "Enable the change trigger or add a timer.", + t.TagId)); + } + } + + /// Read the trigger fields from a calc tag's TagConfig: changeTriggered + /// (default true, the driver's own default) and timerIntervalMs (null when absent or not a + /// number). Never throws — malformed JSON yields the defaults. + private static (bool ChangeTriggered, int? TimerIntervalMs) ParseTriggers(string? tagConfig) + { + if (string.IsNullOrWhiteSpace(tagConfig)) return (true, null); + try + { + using var doc = System.Text.Json.JsonDocument.Parse(tagConfig); + var root = doc.RootElement; + if (root.ValueKind != System.Text.Json.JsonValueKind.Object) return (true, null); + var changeTriggered = true; + if (root.TryGetProperty("changeTriggered", out var ct) + && ct.ValueKind is System.Text.Json.JsonValueKind.False or System.Text.Json.JsonValueKind.True) + changeTriggered = ct.GetBoolean(); + int? timer = null; + if (root.TryGetProperty("timerIntervalMs", out var tm) + && tm.ValueKind == System.Text.Json.JsonValueKind.Number && tm.TryGetInt32(out var ms)) + timer = ms; + return (changeTriggered, timer); + } + catch (System.Text.Json.JsonException) + { + return (true, null); + } } /// Extract the scriptId string from a calc tag's schemaless TagConfig JSON. Never diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.AlarmHistorian/LocalDbStoreAndForwardSink.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.AlarmHistorian/LocalDbStoreAndForwardSink.cs index 8a9b9ec4..6d239f75 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.AlarmHistorian/LocalDbStoreAndForwardSink.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.AlarmHistorian/LocalDbStoreAndForwardSink.cs @@ -92,6 +92,12 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl private bool? _lastGateDecision; private long _queuedRowCount; + // Cached dead-letter depth (R05:7). GetStatus used to run a synchronous COUNT(*) table scan per + // call — one per /healthz probe and per AdminUI poll on the shared LocalDb file. Kept in step by + // every path that flips dead_lettered (drain outcomes, corrupt rows, RetryDeadLettered, retention + // purge) and resynced from storage on the same cadence as _queuedRowCount, so a row the pair peer + // replicates in is visible after the next resync rather than never. + private long _deadLetterRowCount; // Probe counter — incremented every time we actually issue a real COUNT(*) for // capacity enforcement. Public for test instrumentation only. private long _capacityProbeCount; @@ -145,9 +151,16 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl _clock = clock ?? (() => DateTime.UtcNow); _drainGate = drainGate ?? (static () => true); - _queuedRowCount = ProbeQueuedRowCount(); + _queuedRowCount = ProbeRowCount(deadLettered: false); + _deadLetterRowCount = ProbeRowCount(deadLettered: true); } + /// Test-only: re-sync both cached counters (queued + dead-lettered) from storage — the same + /// resync the enqueue cadence drives every enqueues. + /// Cancellation token. + /// A task that completes once both counters match storage. + public Task DebugResyncCountersAsync(CancellationToken ct) => ResyncRowCountsAsync(ct); + /// /// Start the background drain worker. Not started automatically so tests can /// drive deterministically. @@ -260,7 +273,7 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl // has a second way to fall behind that no local code path can observe. if (enqueuesSinceResync >= ResyncEnqueueInterval) { - await ResyncQueuedRowCountAsync(ct).ConfigureAwait(false); + await ResyncRowCountsAsync(ct).ConfigureAwait(false); cached = Interlocked.Read(ref _queuedRowCount); Interlocked.Exchange(ref _enqueuesSinceResync, 0); } @@ -273,22 +286,26 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl await EnforceCapacityAsync(ct).ConfigureAwait(false); } - /// Synchronously query COUNT(*) of non-dead-lettered rows. Used at startup. - private long ProbeQueuedRowCount() + /// Synchronously query COUNT(*) of queued or dead-lettered rows. Used at startup. + private long ProbeRowCount(bool deadLettered) { Interlocked.Increment(ref _capacityProbeCount); using var conn = _db.CreateConnection(); using var cmd = conn.CreateCommand(); - cmd.CommandText = "SELECT COUNT(*) FROM alarm_sf_events WHERE dead_lettered = 0"; + cmd.CommandText = deadLettered + ? "SELECT COUNT(*) FROM alarm_sf_events WHERE dead_lettered = 1" + : "SELECT COUNT(*) FROM alarm_sf_events WHERE dead_lettered = 0"; return (long)(cmd.ExecuteScalar() ?? 0L); } - /// Re-sync the in-memory counter from storage (async path). - private async Task ResyncQueuedRowCountAsync(CancellationToken ct) + /// Re-sync both in-memory counters from storage (async path). + private async Task ResyncRowCountsAsync(CancellationToken ct) { Interlocked.Increment(ref _capacityProbeCount); var live = await CountAsync("dead_lettered = 0", ct).ConfigureAwait(false); Interlocked.Exchange(ref _queuedRowCount, live); + var dead = await CountAsync("dead_lettered = 1", ct).ConfigureAwait(false); + Interlocked.Exchange(ref _deadLetterRowCount, dead); } private async Task CountAsync(string predicate, CancellationToken ct) @@ -356,6 +373,7 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl await corruptTx.CommitAsync(ct).ConfigureAwait(false); } Interlocked.Add(ref _queuedRowCount, -corruptIds.Count); + Interlocked.Add(ref _deadLetterRowCount, corruptIds.Count); _logger.Warning( "Dead-lettered {Count} historian queue row(s) with un-deserializable payload", corruptIds.Count); @@ -405,6 +423,7 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl } int rowsLeavingQueue = 0; + int rowsDeadLettered = 0; await using (var tx = await _db.BeginTransactionAsync(ct).ConfigureAwait(false)) { for (var i = 0; i < outcomes.Count; i++) @@ -423,6 +442,7 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl case HistorianWriteOutcome.PermanentFail: await DeadLetterRowAsync(tx, id, $"permanent fail at {_clock():O}", ct).ConfigureAwait(false); rowsLeavingQueue++; + rowsDeadLettered++; break; case HistorianWriteOutcome.RetryPlease: // finding 002: cap retries so a perpetually-RetryPlease (poison) @@ -434,6 +454,7 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl { await DeadLetterRowAsync(tx, id, $"max attempts ({_maxAttempts}) exceeded", ct).ConfigureAwait(false); rowsLeavingQueue++; + rowsDeadLettered++; } else { @@ -449,6 +470,8 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl // cap (finding 002) — keep the counter aligned. if (rowsLeavingQueue > 0) Interlocked.Add(ref _queuedRowCount, -rowsLeavingQueue); + if (rowsDeadLettered > 0) + Interlocked.Add(ref _deadLetterRowCount, rowsDeadLettered); var acks = outcomes.Count(o => o == HistorianWriteOutcome.Ack); lock (_statusLock) @@ -523,13 +546,9 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl var queued = Interlocked.Read(ref _queuedRowCount); if (queued < 0) queued = 0; - long deadlettered; - using (var conn = _db.CreateConnection()) - using (var cmd = conn.CreateCommand()) - { - cmd.CommandText = "SELECT COUNT(*) FROM alarm_sf_events WHERE dead_lettered = 1"; - deadlettered = (long)(cmd.ExecuteScalar() ?? 0L); - } + // Cached, never a live scan (R05:7) — see the field's remarks for the resync cadence. + var deadlettered = Interlocked.Read(ref _deadLetterRowCount); + if (deadlettered < 0) deadlettered = 0; DateTime? lastDrain, lastSuccess; string? lastError; @@ -568,7 +587,11 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl var revived = cmd.ExecuteNonQuery(); // Dead-lettered rows rejoin the non-dead-lettered queue — keep the in-memory // counter aligned. - if (revived > 0) Interlocked.Add(ref _queuedRowCount, revived); + if (revived > 0) + { + Interlocked.Add(ref _queuedRowCount, revived); + Interlocked.Add(ref _deadLetterRowCount, -revived); + } return revived; } @@ -646,8 +669,9 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl Interlocked.Increment(ref _capacityProbeCount); var count = await CountAsync("dead_lettered = 0", ct).ConfigureAwait(false); - // Resync the in-memory counter while we have a fresh number. + // Resync the in-memory counters while we have a fresh number. Interlocked.Exchange(ref _queuedRowCount, count); + Interlocked.Exchange(ref _deadLetterRowCount, await CountAsync("dead_lettered = 1", ct).ConfigureAwait(false)); if (count < _capacity) return; var toEvict = count - _capacity + 1; @@ -684,7 +708,10 @@ public sealed class LocalDbStoreAndForwardSink : IAlarmHistorianSink, IDisposabl ct).ConfigureAwait(false); if (purged > 0) + { + Interlocked.Add(ref _deadLetterRowCount, -purged); _logger.Information("Purged {Count} dead-lettered row(s) past retention window", purged); + } } private void BumpBackoff() => _backoffIndex = Math.Min(_backoffIndex + 1, BackoffLadder.Length - 1); diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms/ScriptedAlarmEngine.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms/ScriptedAlarmEngine.cs index 4ccc3592..17b513ac 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms/ScriptedAlarmEngine.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms/ScriptedAlarmEngine.cs @@ -73,6 +73,14 @@ public sealed class ScriptedAlarmEngine : IDisposable private readonly Func _clock; private readonly TimeSpan _scriptTimeout; + /// + /// Per-alarm run quarantine (keyed by alarm id, source identity = predicate source). Refuses a + /// predicate run while the alarm's previous (timed-out, abandoned) run is still executing and + /// quarantines after three consecutive timeouts (a refusal is not a strike unless its orphan is stuck past StuckOrphanQuarantineFactor × the budget) or an allocation-budget breach — one orphan + /// per alarm instead of one per upstream push. Reset on every (a redeploy). + /// + private readonly ScriptRunGuard _guard; + // ConcurrentDictionary, not a plain Dictionary: every mutation happens under // _evalGate, but four read paths (GetState, GetAllStates, LoadedAlarmIds, // RunShelvingCheck) touch _alarms from arbitrary threads (Admin UI request @@ -162,6 +170,33 @@ public sealed class ScriptedAlarmEngine : IDisposable => _scratchByAlarmId.TryGetValue(alarmId, out var s) ? s.Context : null; private readonly ConcurrentDictionary _valueCache = new(StringComparer.Ordinal); + + /// Test hook — the number of paths currently held in the value cache. + internal int ValueCacheCountForTest => _valueCache.Count; + + /// Test hook — whether is currently held in the value cache. + internal bool ValueCacheContainsForTest(string path) => _valueCache.ContainsKey(path); + + /// + /// How long waits for in-flight background work (a re-evaluation or shelving + /// check mid-SaveAsync) before cancelling it through and + /// returning. 5 s, like PollGroupEngine's drain; a hung store must not hang host shutdown. + /// + internal TimeSpan DisposeDrainTimeout { get; set; } = TimeSpan.FromSeconds(5); + + /// Cancelled by once the drain bound expires — every background task + /// (DrainDirtyAsync, ShelvingCheckAsync) runs on its token, so a store call that honours + /// cancellation returns instead of outliving the engine. + private readonly CancellationTokenSource _shutdownCts = new(); + + /// 's token, captured once: background work reads this, never the CTS, + /// so can dispose the CTS without racing a late reader. + private readonly CancellationToken _shutdownToken; + + private volatile bool _shutdownCtsDisposed; + + /// Test hook — whether disposed . + internal bool ShutdownCtsDisposedForTest => _shutdownCtsDisposed; private readonly Dictionary> _alarmsReferencing = new(StringComparer.Ordinal); // tag path -> alarm ids @@ -204,13 +239,15 @@ public sealed class ScriptedAlarmEngine : IDisposable /// The logger for engine-level diagnostics. /// Optional function providing the current UTC time; defaults to DateTime.UtcNow. /// Optional timeout for script execution; defaults to the evaluator's default timeout. + /// Run-guard budget + quarantine threshold; null ⇒ defaults. public ScriptedAlarmEngine( ITagUpstreamSource upstream, IAlarmStateStore store, ScriptLoggerFactory loggerFactory, ILogger engineLogger, Func? clock = null, - TimeSpan? scriptTimeout = null) + TimeSpan? scriptTimeout = null, + ScriptingOptions? scripting = null) { _upstream = upstream ?? throw new ArgumentNullException(nameof(upstream)); _store = store ?? throw new ArgumentNullException(nameof(store)); @@ -218,8 +255,21 @@ public sealed class ScriptedAlarmEngine : IDisposable _engineLogger = engineLogger ?? throw new ArgumentNullException(nameof(engineLogger)); _clock = clock ?? (() => DateTime.UtcNow); _scriptTimeout = scriptTimeout ?? TimedScriptEvaluator.DefaultTimeout; + _guard = new ScriptRunGuard(scripting, _engineLogger); + _shutdownToken = _shutdownCts.Token; } + /// The run guard every predicate evaluation goes through (diagnostics / tests). + public ScriptRunGuard RunGuard => _guard; + + /// + /// OPC UA BadInternalError — the quality a condition is annotated with while its predicate + /// cannot be evaluated (timed out, refused because the previous run is still executing, or + /// quarantined). The condition's state is frozen; the quality says why it cannot be trusted. The + /// next completed evaluation restores the input-derived quality through the normal bucket tracking. + /// + private const uint StatusBadInternalError = 0x80020000u; + /// Raised for every emission the Part9StateMachine produces that the engine should publish. public event EventHandler? OnEvent; @@ -259,6 +309,10 @@ public sealed class ScriptedAlarmEngine : IDisposable UnsubscribeFromUpstream(); _alarms.Clear(); _alarmsReferencing.Clear(); + // The value cache is re-seeded below for exactly the paths this generation references. It + // used to survive reloads untouched, so every path a retired alarm had ever referenced stayed + // cached forever — a slow leak over many deploys with a churning tag set. + _valueCache.Clear(); // Drop the prior generation's per-alarm scratch buffers — definitions may // have changed (different Inputs, different Logger), so any reuse would be // unsafe. @@ -268,6 +322,9 @@ public sealed class ScriptedAlarmEngine : IDisposable // recompile this one. Skipping this is what made the earlier fix a // no-op in production. _compileCache.Clear(); + // A (re)load is a deploy: lift every run-guard quarantine (an edited predicate already lifts + // its own through the guard's source identity; this covers "redeployed to retry"). + _guard.ResetAll(); var compileFailures = new List(); foreach (var def in definitions) @@ -284,15 +341,17 @@ public sealed class ScriptedAlarmEngine : IDisposable // Route through CompiledScriptCache so the emitted assembly's // collectible ALC participates in publish-replace cleanup. + // The compiled script is run through _guard (timeout + quarantine) at evaluation time — + // the per-alarm TimedScriptEvaluator this used to wrap gave the timeout but could not + // see that the run it abandoned was still executing. var evaluator = _compileCache.GetOrCompile(def.PredicateScriptSource); - var timed = new TimedScriptEvaluator(evaluator, _scriptTimeout); var logger = _loggerFactory.Create(def.AlarmId); var templateTokens = MessageTemplate.ExtractTokenPaths(def.MessageTemplate); var allInputs = new HashSet(extraction.Reads, StringComparer.Ordinal); foreach (var t in templateTokens) allInputs.Add(t); - _alarms[def.AlarmId] = new AlarmState(def, timed, extraction.Reads, templateTokens, logger, + _alarms[def.AlarmId] = new AlarmState(def, evaluator, extraction.Reads, templateTokens, logger, AlarmConditionState.Fresh(def.AlarmId, _clock())); foreach (var path in allInputs) @@ -546,8 +605,8 @@ public sealed class ScriptedAlarmEngine : IDisposable /// The new data value snapshot. internal void OnUpstreamChange(string path, DataValueSnapshot value) { + if (_disposed) return; // a disposed engine neither caches nor queues — nothing reads it again _valueCache[path] = value; - if (_disposed) return; // don't queue new work against a disposing engine if (!_alarmsReferencing.TryGetValue(path, out var alarmIds)) return; bool startDrain; @@ -562,7 +621,7 @@ public sealed class ScriptedAlarmEngine : IDisposable // Started outside the lock: DrainDirtyAsync runs synchronously up to its // first real await, and nothing it does should happen under _dirtyLock. - if (startDrain) TrackBackgroundTask(() => DrainDirtyAsync(CancellationToken.None)); + if (startDrain) TrackBackgroundTask(() => DrainDirtyAsync(_shutdownToken)); } /// @@ -705,6 +764,11 @@ public sealed class ScriptedAlarmEngine : IDisposable } finally { _evalGate.Release(); } } + catch (OperationCanceledException) when (_shutdownToken.IsCancellationRequested) + { + // Dispose cut the drain short after its bound — expected, not a failure. + return; + } catch (Exception ex) { _engineLogger.Error(ex, "ScriptedAlarmEngine reevaluate failed"); @@ -744,7 +808,6 @@ public sealed class ScriptedAlarmEngine : IDisposable // short-circuit so an outright-Bad input is still observed. A bucket change with no state // transition is delivered out of band as a QualityChanged emission (see below). var worstStatus = WorstInputStatus(scratch.ReadCache); - var qualityBucketChanged = TrackQualityBucket(state.Definition.AlarmId, worstStatus); // Cold-start guard — skip the predicate when any referenced upstream tag has no // cached value yet (the upstream subscription hasn't delivered its first push). @@ -757,7 +820,7 @@ public sealed class ScriptedAlarmEngine : IDisposable // The condition is frozen (can't trust its state), but its source quality just changed // bucket — annotate it out of band so a comms-lost / Bad-input scripted condition reports // Bad, mirroring the native OT path. - if (qualityBucketChanged) + if (TrackQualityBucket(state.Definition.AlarmId, worstStatus)) pendingEmissions.Add(BuildQualityEmission(state, seed, worstStatus)); return seed; } @@ -767,22 +830,41 @@ public sealed class ScriptedAlarmEngine : IDisposable bool predicateTrue; try { - predicateTrue = await state.Evaluator.RunAsync(context, ct).ConfigureAwait(false); + predicateTrue = await _guard.RunAsync( + state.Definition.AlarmId, state.Definition.PredicateScriptSource, state.Evaluator, context, + _scriptTimeout, ct) + .ConfigureAwait(false); } - catch (OperationCanceledException) + catch (OperationCanceledException) when (ct.IsCancellationRequested) { throw; } catch (ScriptTimeoutException tex) { - state.Logger.Warning("Alarm predicate timed out after {Timeout} — state unchanged", tex.Timeout); - return seed; + return PredicateDidNotComplete(state, seed, scratch, + $"timed out after {tex.Timeout.TotalMilliseconds:F0} ms", pendingEmissions); + } + catch (ScriptRunRefusedException ex) + { + return PredicateDidNotComplete(state, seed, scratch, ex.Message, pendingEmissions); + } + catch (ScriptQuarantinedException ex) + { + return PredicateDidNotComplete(state, seed, scratch, ex.Message, pendingEmissions); } catch (Exception ex) { + scratch.LastNonCompletion = null; state.Logger.Error(ex, "Alarm predicate threw — state unchanged"); return seed; } + scratch.LastNonCompletion = null; + + // Track the bucket only once the predicate has COMPLETED (I3). The tracked bucket is the last + // bucket this alarm was annotated with; tracking the input bucket before the attempt flipped it to + // Good on every push, so a refused / quarantined predicate (which annotates Bad) re-emitted + // QualityChanged on every push instead of once per real bucket change. + var qualityBucketChanged = TrackQualityBucket(state.Definition.AlarmId, worstStatus); var result = Part9StateMachine.ApplyPredicate(seed, predicateTrue, nowUtc); var transition = result.Emission != EmissionKind.None @@ -802,6 +884,28 @@ public sealed class ScriptedAlarmEngine : IDisposable return result.State; } + /// + /// The predicate did not return (timed out, refused because the previous run is still executing, or + /// quarantined): hold the condition at , log the reason once per change of + /// reason (a quarantined alarm is re-attempted on every push and would otherwise log every time), + /// and annotate the condition out of band — the frozen state + /// cannot be trusted and the quality is how the operator sees that. The next completed evaluation + /// restores the input-derived quality through the normal bucket tracking. + /// + private AlarmConditionState PredicateDidNotComplete( + AlarmState state, AlarmConditionState seed, AlarmScratch scratch, string reason, + List pendingEmissions) + { + if (!string.Equals(scratch.LastNonCompletion, reason, StringComparison.Ordinal)) + { + scratch.LastNonCompletion = reason; + state.Logger.Warning("Alarm predicate did not complete ({Reason}) — state unchanged, quality Bad", reason); + } + if (TrackQualityBucket(state.Definition.AlarmId, StatusBadInternalError)) + pendingEmissions.Add(BuildQualityEmission(state, seed, StatusBadInternalError)); + return seed; + } + /// /// Refill in place from _valueCache, falling /// back to a synchronous ITagUpstreamSource.ReadTag for paths whose @@ -986,7 +1090,7 @@ public sealed class ScriptedAlarmEngine : IDisposable { if (_disposed) return; var ids = _alarms.Keys.ToArray(); - TrackBackgroundTask(() => ShelvingCheckAsync(ids, CancellationToken.None)); + TrackBackgroundTask(() => ShelvingCheckAsync(ids, _shutdownToken)); } /// @@ -1125,6 +1229,10 @@ public sealed class ScriptedAlarmEngine : IDisposable } finally { _evalGate.Release(); } } + catch (OperationCanceledException) when (_shutdownToken.IsCancellationRequested) + { + return; // Dispose cut the check short after its bound + } catch (Exception ex) { _engineLogger.Warning(ex, "ScriptedAlarmEngine shelving-check failed"); @@ -1165,11 +1273,25 @@ public sealed class ScriptedAlarmEngine : IDisposable // flight can outlive the engine and write to a (possibly disposed) store // after Dispose() has returned. The tasks re-check _disposed after // acquiring the gate and bail out, but the await still has to complete. + // BOUNDED (R05:3): the drained tasks end in IAlarmStateStore.SaveAsync, and a stalled store + // (connection stall, lock, replication hiccup) used to hang this — and the host shutdown that + // calls it — indefinitely. Wait DisposeDrainTimeout; past it, cancel the tasks' shared token (a + // store that honours cancellation returns promptly), log, and give them one short grace period. Task[] toAwait; lock (_inFlightLock) { toAwait = [.. _inFlight]; } if (toAwait.Length > 0) { - try { Task.WhenAll(toAwait).GetAwaiter().GetResult(); } + var all = Task.WhenAll(toAwait); + try { all.WaitAsync(DisposeDrainTimeout).GetAwaiter().GetResult(); } + catch (TimeoutException) + { + _engineLogger.Warning( + "ScriptedAlarmEngine dispose: {Count} background task(s) still running after {Timeout} — cancelling them (a store call is stalled)", + toAwait.Length, DisposeDrainTimeout); + _shutdownCts.Cancel(); + try { all.WaitAsync(TimeSpan.FromSeconds(1)).GetAwaiter().GetResult(); } + catch (Exception) { /* cancelled, faulted, or still stuck — we are leaving either way */ } + } catch (Exception ex) { // Background task failures already logged inside ReevaluateAsync / @@ -1192,6 +1314,16 @@ public sealed class ScriptedAlarmEngine : IDisposable _alarmsReferencing.Clear(); _scratchByAlarmId.Clear(); _lastQualityBucketByAlarmId.Clear(); + + // Release the shutdown CTS once nothing can still be observing it through a registration: every + // drained task has completed. A task still stuck past the grace keeps its registration, so the CTS is + // left to the GC in that case (logged above). + if (toAwait.All(t => t.IsCompleted)) + { + _shutdownCts.Dispose(); + _shutdownCtsDisposed = true; + } + // Dispose every compiled-predicate ALC so the engine's shutdown actually // releases the emitted assemblies. The drain above ensures no evaluator is // mid-call; CompiledScriptCache.Dispose internally guards against use-after- @@ -1201,7 +1333,7 @@ public sealed class ScriptedAlarmEngine : IDisposable private sealed record AlarmState( ScriptedAlarmDefinition Definition, - TimedScriptEvaluator Evaluator, + ScriptEvaluator Evaluator, IReadOnlySet Inputs, IReadOnlyList TemplateTokens, ILogger Logger, @@ -1227,6 +1359,10 @@ public sealed class ScriptedAlarmEngine : IDisposable /// Gets the predicate evaluation context. public AlarmPredicateContext Context { get; } + /// The reason the last evaluation did not complete (timeout / refused / quarantined), or null + /// after a completed run — the once-per-change log gate for PredicateDidNotComplete. + public string? LastNonCompletion { get; set; } + /// /// Initializes a new AlarmScratch with the specified inputs, logger, and clock. /// diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms/ScriptedAlarmSource.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms/ScriptedAlarmSource.cs index dc76923c..9d44aee5 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms/ScriptedAlarmSource.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms/ScriptedAlarmSource.cs @@ -1,4 +1,5 @@ using System.Collections.Concurrent; +using Serilog; using ZB.MOM.WW.OtOpcUa.Core.Abstractions; namespace ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms; @@ -23,19 +24,27 @@ namespace ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms; /// adapter doesn't maintain per-subscription state beyond the filter set — it /// checks each emission against every live subscription. /// +/// +/// A throwing subscriber is logged at Warning (naming the alarm) and +/// does not crash the adapter — the same posture as the engine's own FireEvent. It used to +/// be swallowed silently: a lost alarm event with no trace. +/// /// public sealed class ScriptedAlarmSource : IAlarmSource, IDisposable { private readonly ScriptedAlarmEngine _engine; + private readonly ILogger _logger; private readonly ConcurrentDictionary _subscriptions = new(StringComparer.Ordinal); private bool _disposed; /// Initializes a new instance of the class. /// The scripted alarm engine to expose. - public ScriptedAlarmSource(ScriptedAlarmEngine engine) + /// Where a throwing subscriber is reported; null ⇒ Serilog's global logger. + public ScriptedAlarmSource(ScriptedAlarmEngine engine, ILogger? logger = null) { _engine = engine ?? throw new ArgumentNullException(nameof(engine)); + _logger = logger ?? Log.Logger; _engine.OnEvent += OnEngineEvent; } @@ -98,7 +107,13 @@ public sealed class ScriptedAlarmSource : IAlarmSource, IDisposable Severity: evt.Severity, SourceTimestampUtc: evt.TimestampUtc); try { OnAlarmEvent?.Invoke(this, payload); } - catch { /* subscriber exceptions don't crash the adapter */ } + catch (Exception ex) + { + // Subscriber exceptions don't crash the adapter — but they are not silent either: a lost + // alarm event must leave a trace the operator can find. + _logger.Warning(ex, "ScriptedAlarmSource OnAlarmEvent subscriber threw for {AlarmId} ({Emission})", + evt.AlarmId, evt.Emission); + } } } diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ForbiddenTypeAnalyzer.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ForbiddenTypeAnalyzer.cs index 005734b6..5f7d8140 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ForbiddenTypeAnalyzer.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ForbiddenTypeAnalyzer.cs @@ -17,13 +17,15 @@ namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; /// /// /// -/// Deny-list is the authoritative Phase 7 plan set: +/// Deny-list is the authoritative Phase 7 plan set, hardened since: /// System.IO, System.Net, System.Diagnostics, -/// System.Reflection, System.Threading.Thread, -/// System.Threading.Tasks (scripts are synchronous predicates — no -/// legitimate need to start background tasks; a Task.Run fan-out outlives -/// the evaluation timeout entirely), System.Runtime.InteropServices, -/// Microsoft.Win32. +/// System.Reflection, System.Threading.Tasks and the whole of +/// System.Threading (scripts are synchronous predicates — no legitimate need +/// to start background work, and no blocking primitive may park the evaluation's pool +/// thread past its budget; CancellationToken / Interlocked / +/// Volatile are allow-listed back in), System.Runtime.InteropServices, +/// System.Runtime.Loader, Microsoft.Win32; plus the member-granular +/// (System.Type's reflection entry points). /// /// /// Deny-list prefix match. System.Net catches System.Net.Http, @@ -63,13 +65,19 @@ public static class ForbiddenTypeAnalyzer "System.Net", "System.Diagnostics", // catches Process, ProcessStartInfo, EventLog, Trace/Debug file sinks "System.Reflection", - // System.Threading.Thread is NOT in this list: Thread's containing namespace is - // "System.Threading" (not "System.Threading.Thread"), so a prefix check on - // "System.Threading.Thread" never matches. Thread is denied type-granularly via - // ForbiddenFullTypeNames instead so the check actually fires. "System.Threading.Tasks", // Task.Run / Parallel — scripts are synchronous predicates // and have no legitimate need to start background work; // a Task fan-out outlives the evaluation timeout entirely. + // Listed BEFORE the parent prefix so its rejection names it. + "System.Threading", // Thread / ThreadPool / Timer (background work that outlives + // the timeout) AND every blocking primitive — SemaphoreSlim, + // Monitor, SpinWait, ManualResetEvent(Slim), Mutex, + // EventWaitHandle — which park the script's pool thread past + // its budget (the same orphan ScriptRunGuard exists to bound) + // and, for the named kernel objects, touch system-global + // state. The few sync-free primitives a script may + // legitimately name are allow-listed in + // AllowedTypesInForbiddenNamespaces. "System.Runtime.InteropServices", "System.Runtime.Loader", // AssemblyLoadContext + AssemblyDependencyResolver — // arbitrary DLL load into the host process. @@ -79,11 +87,55 @@ public static class ForbiddenTypeAnalyzer "Microsoft.Win32", // registry ]; + /// + /// Types that stay reachable although their namespace is in + /// . Matched by exact fully-qualified name against the + /// resolved type symbol (generic constructions unwrapped). The whole of System.Threading is + /// denied; these three are the sync-free primitives with no blocking surface — a + /// is read-only state, and + /// are single-instruction memory operations. + /// + public static readonly IReadOnlyList AllowedTypesInForbiddenNamespaces = + [ + "System.Threading.CancellationToken", + "System.Threading.Interlocked", + "System.Threading.Volatile", + ]; + + /// + /// Members scripts are NOT allowed to call on otherwise-allowed types, as + /// (declaring type, member name). System.Type must stay reachable + /// (typeof, Name, IsValueType are ordinary metadata reads) but its reflection + /// entry points obtain a type or member by NAME — Type.GetType("System.IO.File") reaches a + /// forbidden type without ever naming it syntactically, and GetMethod* / GetProperty + /// / InvokeMember / … hand back a System.Reflection handle (which pass 2 catches when + /// declared, but not when consumed inline). Instance object.GetType() is declared on + /// System.Object and is not matched. + /// + public static readonly IReadOnlyList<(string Type, string Member)> ForbiddenMembers = + [ + ("System.Type", "GetType"), + ("System.Type", "GetMethod"), + ("System.Type", "GetMethods"), + ("System.Type", "InvokeMember"), + ("System.Type", "GetProperty"), + ("System.Type", "GetProperties"), + ("System.Type", "GetField"), + ("System.Type", "GetFields"), + ("System.Type", "GetMember"), + ("System.Type", "GetMembers"), + ("System.Type", "GetConstructor"), + ("System.Type", "GetConstructors"), + ("System.Type", "GetEvent"), + ("System.Type", "GetEvents"), + ("System.Type", "GetDefaultMembers"), + ]; + /// /// Fully-qualified type names scripts are NOT allowed to reference, regardless of /// namespace. Used when a dangerous type shares its namespace with legitimate types - /// (e.g. System.Threading hosts both CancellationToken and - /// Thread) so a namespace-prefix rule would over-block. Matched by exact + /// (e.g. System.Runtime.CompilerServices hosts both MethodImplOptions and + /// RuntimeHelpers) so a namespace-prefix rule would over-block. Matched by exact /// fully-qualified name against the resolved type symbol — every member of /// the type (including read-only ones) is therefore rejected. /// @@ -99,19 +151,22 @@ public static class ForbiddenTypeAnalyzer /// System.Activator — CreateInstance is a /// reflection-equivalent escape that constructs a forbidden type by name /// without ever naming it syntactically. - /// System.Threading.Thread — raw thread creation bypasses the - /// per-evaluation timeout; denied type-granularly because its containing - /// namespace is System.Threading (shared with allowed types like - /// CancellationToken), so a namespace-prefix rule cannot reach it - /// without blocking unrelated types. - /// System.Threading.ThreadPool / System.Threading.Timer — - /// background-work vectors that outlive the per-evaluation timeout; same - /// threat as Task.Run. /// System.Runtime.CompilerServices.Unsafe — exposes raw type- /// reinterpretation (As<TFrom,TTo>, As<T>(object)) /// that bypasses the CLR type system without requiring an unsafe context at /// the call site; enables type-confusion and managed heap corruption. + /// System.Runtime.CompilerServices.RuntimeHelpers — + /// GetUninitializedObject constructs an instance of any type (a forbidden + /// one included) with no constructor and no syntactic type name beyond a + /// Type value; PrepareMethod / RunClassConstructor reach + /// runtime internals. /// + /// + /// System.Threading.Thread / ThreadPool / Timer used to be listed + /// here; since the whole System.Threading namespace is denied (with a type-granular + /// allow-list, see ) the prefix rule reaches + /// them first. + /// /// public static readonly IReadOnlyList ForbiddenFullTypeNames = [ @@ -119,26 +174,6 @@ public static class ForbiddenTypeAnalyzer "System.AppDomain", "System.GC", "System.Activator", - // System.Threading.Thread lives in the System.Threading namespace (shared with - // CancellationToken, SemaphoreSlim, etc.), so a namespace-prefix deny-list cannot - // target it without blocking those legitimate types. Denied type-granularly here. - "System.Threading.Thread", - // Broadening the references list to the BCL trusted-platform-assemblies set - // re-exposed two background-work vectors the original deny-list missed. Both live - // in System.Threading (shared with allowed sync primitives like CancellationToken / - // SemaphoreSlim), so they must be denied type-granularly: - // - // System.Threading.ThreadPool — QueueUserWorkItem / UnsafeQueueUserWorkItem - // re-introduce the background-fanout threat - // closed against System.Threading.Tasks. - // System.Threading.Timer — Timer(callback, …) schedules unbounded work - // that outlives the per-evaluation timeout. - // - // System.Runtime.Loader.AssemblyLoadContext is also covered, but at the namespace- - // prefix level above (System.Runtime.Loader) so future BCL additions to that - // namespace are denied by default. - "System.Threading.ThreadPool", - "System.Threading.Timer", // System.Runtime.CompilerServices.Unsafe exposes raw type-reinterpretation // (Unsafe.As, Unsafe.As(object)) that bypasses the CLR type system // without requiring an 'unsafe' compilation context at the call site. In a script, @@ -148,6 +183,11 @@ public static class ForbiddenTypeAnalyzer // compile-time-only types (CallerMemberNameAttribute, MethodImplAttribute, // MethodImplOptions) that scripts may legitimately reference. "System.Runtime.CompilerServices.Unsafe", + // RuntimeHelpers.GetUninitializedObject(Type) builds an instance of ANY type — a + // forbidden one obtained through Type.GetType (itself denied via ForbiddenMembers) + // included — without a constructor or a syntactic type name. Same namespace caveat + // as Unsafe above, so type-granular. + "System.Runtime.CompilerServices.RuntimeHelpers", ]; /// @@ -277,28 +317,61 @@ public static class ForbiddenTypeAnalyzer if (rejections.Any(r => r.Span == span && r.TypeName == typeName)) return; - var ns = typeSymbol.ContainingNamespace?.ToDisplayString() ?? string.Empty; - foreach (var forbidden in ForbiddenNamespacePrefixes) - { - if (ns == forbidden || ns.StartsWith(forbidden + ".", StringComparison.Ordinal)) - { - rejections.Add(new ForbiddenTypeRejection( - Span: span, - TypeName: typeName, - Namespace: ns, - Message: $"Type '{typeName}' is in the forbidden namespace '{ns}'. " + - $"Scripts cannot reach {forbidden}* per Phase 7 sandbox rules.")); - return; - } - } - - // Type-granular deny-list — dangerous types that live in the allow-listed - // System namespace and so cannot be caught by ForbiddenNamespacePrefixes. - // Matched on the full type name; OriginalDefinition unwraps any generic - // construction before naming. + // Full name of the (unwrapped) type — shared by the allow-list, the type deny-list and the + // member deny-list below. OriginalDefinition unwraps any generic construction before naming. var fullTypeName = typeSymbol.OriginalDefinition.ToDisplayString( SymbolDisplayFormat.FullyQualifiedFormat.WithGlobalNamespaceStyle( SymbolDisplayGlobalNamespaceStyle.Omitted)); + + var ns = typeSymbol.ContainingNamespace?.ToDisplayString() ?? string.Empty; + + // Member deny-list first: the containing type (System.Type) is allowed, so neither list + // below would ever look at the member name. + if (symbol is IMethodSymbol method) + { + var declaring = method.ContainingType.OriginalDefinition.ToDisplayString( + SymbolDisplayFormat.FullyQualifiedFormat.WithGlobalNamespaceStyle( + SymbolDisplayGlobalNamespaceStyle.Omitted)); + foreach (var (type, member) in ForbiddenMembers) + { + if (declaring == type && method.Name == member) + { + rejections.Add(new ForbiddenTypeRejection( + Span: span, + TypeName: $"{type}.{member}", + Namespace: ns, + Message: $"Member '{type}.{member}' is on the sandbox forbidden-member deny-list: " + + "it obtains a type or member by name, which bypasses the type allow-list " + + "(see ForbiddenTypeAnalyzer.ForbiddenMembers for the authoritative list).")); + return; + } + } + } + + // A type on the allow-list stays reachable even though its namespace is denied; it is still + // subject to the type-granular deny-list below (nothing is on both today). + var allowListed = AllowedTypesInForbiddenNamespaces.Contains(fullTypeName, StringComparer.Ordinal); + + if (!allowListed) + { + foreach (var forbidden in ForbiddenNamespacePrefixes) + { + if (ns == forbidden || ns.StartsWith(forbidden + ".", StringComparison.Ordinal)) + { + rejections.Add(new ForbiddenTypeRejection( + Span: span, + TypeName: typeName, + Namespace: ns, + Message: $"Type '{typeName}' is in the forbidden namespace '{ns}'. " + + $"Scripts cannot reach {forbidden}* per Phase 7 sandbox rules.")); + return; + } + } + } + + // Type-granular deny-list — dangerous types that live in an allow-listed namespace + // (System, System.Runtime.CompilerServices) and so cannot be caught by + // ForbiddenNamespacePrefixes. foreach (var forbiddenType in ForbiddenFullTypeNames) { if (fullTypeName == forbiddenType) diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/IScriptQuarantineOwner.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/IScriptQuarantineOwner.cs new file mode 100644 index 00000000..3cf38fac --- /dev/null +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/IScriptQuarantineOwner.cs @@ -0,0 +1,15 @@ +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; + +/// +/// Implemented by a script seam that runs its scripts through a , so the +/// host that drives its deploy boundary can lift every quarantine on a redeploy (the guard's own +/// source-change detection covers an edited script; this covers "the operator redeployed to retry"). +/// +public interface IScriptQuarantineOwner +{ + /// Lift every quarantine and forget every consecutive-timeout count (). + void ResetQuarantines(); + + /// The script keys currently quarantined. + IReadOnlyCollection QuarantinedScripts { get; } +} diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogCompanionSink.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogCompanionSink.cs index fb1aff35..84bb0e04 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogCompanionSink.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogCompanionSink.cs @@ -24,22 +24,32 @@ namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; /// Original exception (if any) is attached so the main log's diagnostics keep /// the full stack trace. /// +/// +/// Rate-limited per script. A predicate that throws on every push would otherwise mirror +/// one Warning per push into the main log; a keyed by script +/// name admits 20 per minute and mirrors one summary line for the rest when the window rolls. The +/// scripts-*.log file sink is unaffected and keeps the full stream. +/// /// public sealed class ScriptLogCompanionSink : ILogEventSink { private readonly ILogger _mainLogger; private readonly LogEventLevel _minMirrorLevel; + private readonly ScriptLogRateLimiter _limiter; /// Initializes a new instance of the ScriptLogCompanionSink. /// The companion logger to mirror events to. /// The minimum log level to mirror (default: Error). - public ScriptLogCompanionSink(ILogger mainLogger, LogEventLevel minMirrorLevel = LogEventLevel.Error) + /// Per-script rate limiter; null ⇒ the default 20 per minute. + public ScriptLogCompanionSink(ILogger mainLogger, LogEventLevel minMirrorLevel = LogEventLevel.Error, + ScriptLogRateLimiter? limiter = null) { _mainLogger = mainLogger ?? throw new ArgumentNullException(nameof(mainLogger)); _minMirrorLevel = minMirrorLevel; + _limiter = limiter ?? new ScriptLogRateLimiter(); } - /// Emits a log event to the companion logger if it meets the minimum level. + /// Emits a log event to the companion logger if it meets the minimum level and the script is within its per-minute budget. /// The log event to emit. public void Emit(LogEvent logEvent) { @@ -54,6 +64,15 @@ public sealed class ScriptLogCompanionSink : ILogEventSink scriptName = s; } + var admission = _limiter.Admit(scriptName); + if (admission.SuppressedInPreviousWindow > 0) + { + _mainLogger.Warning( + "[Script] {ScriptName}: {SuppressedCount} further script error(s) were suppressed in the previous {WindowSeconds:F0} s; see scripts-*.log", + scriptName, admission.SuppressedInPreviousWindow, _limiter.Window.TotalSeconds); + } + if (!admission.Admitted) return; + var rendered = logEvent.RenderMessage(); if (logEvent.Exception is not null) { diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogRateLimiter.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogRateLimiter.cs new file mode 100644 index 00000000..5cce5fcd --- /dev/null +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogRateLimiter.cs @@ -0,0 +1,126 @@ +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; + +/// +/// Per-source fixed-window rate limit for the script-log fan-out: the first +/// entries a source emits in a are +/// admitted, the rest are counted and dropped, and the count is handed back exactly once — on the first +/// admission after the window rolls — so the caller can emit one summary line in the dropped entries' +/// place. Nothing is silently lost (the operator sees "N suppressed"), and one chatty script cannot +/// shed every other script's entries out of the bounded telemetry channels (drop-oldest) or flood the +/// cluster bus / main log. +/// +/// +/// Used by (key = script + virtual-tag + alarm identity), +/// (key = script name) and the virtual-tag actor's per-failure +/// log (one key per tag). Thread-safe; Serilog invokes a sink on whichever thread logged. Idle sources +/// are swept every admissions so a churning tag set cannot grow the table +/// without bound. +/// +public sealed class ScriptLogRateLimiter +{ + /// Entries admitted per source per window by default: 20. + public const int DefaultLimitPerWindow = 20; + + /// The default window: one minute. + public static readonly TimeSpan DefaultWindow = TimeSpan.FromMinutes(1); + + private const int SweepEvery = 256; + + private readonly Dictionary _sources = new(StringComparer.Ordinal); + private readonly int _limit; + private readonly TimeSpan _window; + private readonly Func _clock; + private int _admitsSinceSweep; + + /// Initializes a limiter. + /// Entries admitted per source per window; values below 1 are treated as 1. + /// The fixed window; null ⇒ . + /// UTC clock; null ⇒ . + public ScriptLogRateLimiter(int limitPerWindow = DefaultLimitPerWindow, TimeSpan? window = null, Func? clock = null) + { + _limit = Math.Max(1, limitPerWindow); + _window = window is { } w && w > TimeSpan.Zero ? w : DefaultWindow; + _clock = clock ?? (static () => DateTime.UtcNow); + } + + /// Entries admitted per source per window, as configured (after clamping to at least 1). + public int LimitPerWindow => _limit; + + /// The window length. + public TimeSpan Window => _window; + + /// + /// Ask whether 's next entry may be emitted. When the window has rolled + /// since the last call, carries the + /// number of entries dropped in the window that just closed (zero otherwise) — the caller emits one + /// summary for them BEFORE the admitted entry. + /// + /// Identity of the emitting script instance. + /// The admission decision. + public ScriptLogAdmission Admit(string sourceKey) + { + ArgumentNullException.ThrowIfNull(sourceKey); + var now = _clock(); + lock (_sources) + { + if (++_admitsSinceSweep >= SweepEvery) + { + _admitsSinceSweep = 0; + Sweep(now); + } + + if (!_sources.TryGetValue(sourceKey, out var source)) + { + source = new Source { WindowStart = now }; + _sources[sourceKey] = source; + } + + long summary = 0; + if (now - source.WindowStart >= _window) + { + summary = source.Suppressed; + source.WindowStart = now; + source.Admitted = 0; + source.Suppressed = 0; + } + + source.LastSeen = now; + if (source.Admitted < _limit) + { + source.Admitted++; + return new ScriptLogAdmission(true, summary); + } + + source.Suppressed++; + return new ScriptLogAdmission(false, summary); + } + } + + private void Sweep(DateTime now) + { + var idle = now - (_window + _window); + List? dead = null; + foreach (var (key, source) in _sources) + { + // A source that still has a pending summary is kept: its next entry must report the count. + if (source.LastSeen < idle && source.Suppressed == 0) + (dead ??= []).Add(key); + } + if (dead is null) return; + foreach (var key in dead) _sources.Remove(key); + } + + private sealed class Source + { + public DateTime WindowStart; + public DateTime LastSeen; + public int Admitted; + public long Suppressed; + } +} + +/// Result of . +/// Whether the entry may be emitted. +/// Entries dropped in the window that just closed — non-zero at +/// most once per window roll; the caller emits one summary line for them. +public readonly record struct ScriptLogAdmission(bool Admitted, long SuppressedInPreviousWindow); diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogTopicSink.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogTopicSink.cs index fe9e7f3e..88bdd973 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogTopicSink.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogTopicSink.cs @@ -25,25 +25,37 @@ namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; /// property so pipelines that pre-date this sink continue to work correctly. If /// neither property is present ScriptId defaults to "unknown". /// +/// +/// Rate-limited per source. A script that logs at Information on every evaluation of a 1 Hz +/// input put one rendered string per second per script onto the cluster bus; 200 such scripts shed +/// everyone's entries out of the bounded telemetry channels. A +/// keyed by the entry's identity (script + virtual tag + alarm) admits 20 entries per minute per +/// source and publishes one summary entry naming the dropped count when the window rolls. +/// /// public sealed class ScriptLogTopicSink : ILogEventSink { private readonly IScriptLogPublisher _publisher; private readonly LogEventLevel _min; + private readonly ScriptLogRateLimiter _limiter; /// Initializes a new instance of the class. /// The publisher that routes entries to the cluster bus. Must not be null. /// Minimum log level to forward. Events below this level are discarded (default: ). + /// Per-source rate limiter; null ⇒ the default 20 per minute. /// Thrown when is null. - public ScriptLogTopicSink(IScriptLogPublisher publisher, LogEventLevel min = LogEventLevel.Information) + public ScriptLogTopicSink(IScriptLogPublisher publisher, LogEventLevel min = LogEventLevel.Information, + ScriptLogRateLimiter? limiter = null) { _publisher = publisher ?? throw new ArgumentNullException(nameof(publisher)); _min = min; + _limiter = limiter ?? new ScriptLogRateLimiter(); } /// /// Converts the to a and - /// publishes it, unless the event is below the configured minimum level. + /// publishes it, unless the event is below the configured minimum level or the source is over its + /// per-minute budget. /// /// The Serilog event to process. Silently ignored when null. public void Emit(LogEvent logEvent) @@ -56,15 +68,36 @@ public sealed class ScriptLogTopicSink : ILogEventSink ? s : null; + var scriptId = P(ScriptLoggerFactory.ScriptIdProperty) + ?? P(ScriptLoggerFactory.ScriptNameProperty) + ?? "unknown"; + var virtualTagId = P(ScriptLoggerFactory.VirtualTagIdProperty); + var alarmId = P(ScriptLoggerFactory.AlarmIdProperty); + var equipmentId = P(ScriptLoggerFactory.EquipmentIdProperty); + + var admission = _limiter.Admit(string.Concat(scriptId, "|", virtualTagId, "|", alarmId)); + if (admission.SuppressedInPreviousWindow > 0) + { + _publisher.Publish(new ScriptLogEntry( + ScriptId: scriptId, + Level: nameof(LogEventLevel.Warning), + Message: $"{admission.SuppressedInPreviousWindow} script-log entr{(admission.SuppressedInPreviousWindow == 1 ? "y" : "ies")} " + + $"from this source were suppressed in the previous {_limiter.Window.TotalSeconds:F0} s " + + $"(limit {_limiter.LimitPerWindow}/window); see scripts-*.log for the full stream", + TimestampUtc: logEvent.Timestamp.UtcDateTime, + VirtualTagId: virtualTagId, + AlarmId: alarmId, + EquipmentId: equipmentId)); + } + if (!admission.Admitted) return; + _publisher.Publish(new ScriptLogEntry( - ScriptId: P(ScriptLoggerFactory.ScriptIdProperty) - ?? P(ScriptLoggerFactory.ScriptNameProperty) - ?? "unknown", + ScriptId: scriptId, Level: logEvent.Level.ToString(), Message: logEvent.RenderMessage(), TimestampUtc: logEvent.Timestamp.UtcDateTime, - VirtualTagId: P(ScriptLoggerFactory.VirtualTagIdProperty), - AlarmId: P(ScriptLoggerFactory.AlarmIdProperty), - EquipmentId: P(ScriptLoggerFactory.EquipmentIdProperty))); + VirtualTagId: virtualTagId, + AlarmId: alarmId, + EquipmentId: equipmentId)); } } diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs new file mode 100644 index 00000000..de1afee2 --- /dev/null +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs @@ -0,0 +1,420 @@ +using System.Collections.Concurrent; +using System.Diagnostics; +using System.Diagnostics.Metrics; +using Serilog; +using ZB.MOM.WW.OtOpcUa.Commons.Observability; + +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; + +/// +/// Per-script run quarantine shared by every script seam on the node. Wraps each evaluation of a +/// with the wall-clock timeout +/// used to provide, and adds what that wrapper +/// could not: knowledge of whether the script it abandoned is still running. +/// +/// +/// +/// The leak this closes. A timed-out script is abandoned, not stopped — a CPU-bound +/// while(true) keeps its thread-pool thread forever. Each seam re-evaluated on every trigger, +/// so a runaway script on a 1 Hz input leaked one pool thread per second until the pool starved and +/// unrelated work (Akka dispatchers, the OPC UA publish thread, gRPC) stalled. The guard keys every +/// run by script instance and: +/// +/// +/// Refuses to start a run while that script's previous run is still executing — +/// (), counted on +/// . One orphan per script, never one per trigger. +/// Quarantines after +/// consecutive timeouts (only a timeout is a strike; a refusal is a Bad publish plus its counter +/// and leaves the streak untouched — on a 1 Hz trigger with a 2 s budget one 4 s overrun is a +/// timeout plus two refusals and must not quarantine; a run that returns — a value or a throw — +/// resets the streak), or on a refusal behind a stuck orphan — one that has been executing for +/// longer than × the timeout (20 s at the +/// 2 s default), which is how a never-returning while(true) (one timeout, then only refusals) +/// gets quarantined: no further dispatch, every attempt throws +/// , one Error log, one otopcua.script.quarantined +/// increment, one event. Lifted by a source change (the operator fixed the +/// script — a new source identity under the same key starts clean and the old orphan no longer blocks +/// it), by on redeploy, or by . +/// Quarantines on an allocation-budget breach: the run's own-thread allocation is sampled +/// with around the script delegate and compared +/// with . This is observation after the fact — a +/// single run that allocates enough to OOM the process is not stopped; that needs an out-of-process +/// runner. +/// +/// +/// The timeout clock starts when the script starts, not when it is queued. The run is pushed to +/// the pool (a CPU-bound script would otherwise execute inline and return an already-completed task +/// that no timeout can fire on), and the wait only begins once the pool has actually picked the run +/// up — so thread-pool starvation is charged to nobody's script. A caller-supplied cancellation wins +/// over the timeout (, never +/// ) so shutdown paths are not misread as timeouts. +/// +/// +/// Cancellation reaches the evaluator, not (yet) the script. On timeout the token handed to +/// is cancelled; a script can only observe +/// it once ScriptContext exposes it (follow-up — the context type lives in the Abstractions +/// project). +/// +/// +public sealed class ScriptRunGuard +{ + /// Failure reason a seam publishes when a run was refused because the previous one is still executing. + public const string PreviousRunStillRunningReason = "previous evaluation still running"; + + /// Prefix of every quarantine reason / message. + public const string QuarantinedReasonPrefix = "script quarantined: "; + + /// + /// Counter otopcua.script.quarantined (Prometheus: otopcua_script_quarantined): one + /// increment per script quarantined, tagged reason = timeouts | stuck | allocation. + /// + public static readonly Counter QuarantinedCounter = + OtOpcUaTelemetry.Meter.CreateCounter("otopcua.script.quarantined", unit: "{script}", + description: "Scripts quarantined by the run guard (reason: timeouts | stuck | allocation)."); + + /// + /// Counter otopcua.script.run_refused: runs refused because the script's previous run was + /// still executing. + /// + public static readonly Counter RefusedCounter = + OtOpcUaTelemetry.Meter.CreateCounter("otopcua.script.run_refused", unit: "{run}", + description: "Script runs refused because the previous run of the same script was still executing."); + + private readonly ConcurrentDictionary _keys = new(StringComparer.Ordinal); + private readonly long _maxAllocBytesPerRun; + private readonly int _quarantineThreshold; + private readonly double _stuckFactor; + private readonly ILogger _logger; + private int _inFlight; + private long _started; + private long _refused; + private long _quarantined; + + /// Initializes a new guard. + /// Budget + threshold; null ⇒ defaults. + /// Where the quarantine Error line goes; null ⇒ Serilog's global logger. + public ScriptRunGuard(ScriptingOptions? options = null, ILogger? logger = null) + { + options ??= new ScriptingOptions(); + _maxAllocBytesPerRun = options.MaxAllocBytesPerRun; + _quarantineThreshold = Math.Max(1, options.QuarantineAfterConsecutiveTimeouts); + _stuckFactor = options.StuckOrphanQuarantineFactor; + _logger = logger ?? Log.Logger; + } + + /// Raised (on the thread that detected it) when a script is quarantined. + public event EventHandler? Quarantined; + + /// Runs currently executing on a pool thread — abandoned (timed-out) orphans included. + public int InFlightCount => Volatile.Read(ref _inFlight); + + /// Runs actually dispatched to the pool, lifetime. + public long StartedRunCount => Interlocked.Read(ref _started); + + /// Runs refused because the same script's previous run was still executing, lifetime. + public long RefusedWhileRunningCount => Interlocked.Read(ref _refused); + + /// Scripts quarantined, lifetime (a reset and re-quarantine counts twice). + public long QuarantinedCount => Interlocked.Read(ref _quarantined); + + /// The keys currently quarantined. + public IReadOnlyCollection QuarantinedKeys => + _keys.Where(kv => kv.Value.QuarantineReason is not null).Select(kv => kv.Key).ToArray(); + + /// Whether is quarantined, and why. + /// The script instance key. + /// The quarantine reason (prefixed ), or null. + /// true when quarantined. + public bool IsQuarantined(string key, out string? reason) + { + reason = _keys.TryGetValue(key, out var state) ? state.QuarantineReason : null; + return reason is not null; + } + + /// + /// Forget everything about : clears its quarantine and its consecutive count, and + /// abandons its in-flight slot (an orphan still running keeps counting on + /// until it finishes, but no longer blocks the key). + /// + /// The script instance key. + public void Reset(string key) => _keys.TryRemove(key, out _); + + /// + /// for every key — the redeploy / compile-cache-clear boundary. Orphans keep + /// counting on until they finish. + /// + public void ResetAll() => _keys.Clear(); + + /// + /// Run against under the guard. + /// + /// The script context type. + /// The script result type. + /// The script instance key (virtual-tag id, calc-tag RawPath, alarm id). + /// + /// The script source (or its hash). A change under the same key clears the key's quarantine and + /// abandons its orphan slot — the operator fixed the script. Null ⇒ not tracked. + /// + /// The compiled script. + /// The script's ctx. + /// Wall-clock budget, measured from the moment the pool starts the run. + /// Caller cancellation; wins over the timeout. + /// The script's result. + /// The key is (or just became) quarantined. + /// The key's previous run is still executing. + /// The run exceeded . + /// was cancelled. + public async Task RunAsync( + string key, + string? sourceIdentity, + ScriptEvaluator evaluator, + TContext context, + TimeSpan timeout, + CancellationToken ct = default) + where TContext : ScriptContext + { + ArgumentNullException.ThrowIfNull(key); + ArgumentNullException.ThrowIfNull(evaluator); + ArgumentNullException.ThrowIfNull(context); + if (timeout <= TimeSpan.Zero) throw new ArgumentOutOfRangeException(nameof(timeout), "Timeout must be positive."); + + var state = Admit(key, sourceIdentity); + + // Slot acquisition is the whole mechanism: a second trigger landing while the previous run (orphan or + // not) still holds the slot is refused here, before anything is dispatched to the pool. + if (Interlocked.CompareExchange(ref state.InFlight, 1, 0) != 0) + { + // A refusal is a Bad publish plus its counter — NOT a strike. Only a timeout (and an allocation + // breach) counts toward quarantine: on a 1 Hz trigger with a 2 s budget a single 4 s overrun is + // one timeout followed by two refusals, and counting those would quarantine a script that merely + // ran long once. The refusal also leaves the timeout streak untouched. + Interlocked.Increment(ref _refused); + RefusedCounter.Add(1, new KeyValuePair("script", key)); + // …unless the orphan is STUCK: a never-returning script times out once and is then only ever + // refused, so the timeout streak alone would never quarantine it. Past the stuck threshold the + // refusal itself quarantines (same path: Error log, metric, Bad, lifted on redeploy/source change). + if (_stuckFactor > 0 && Volatile.Read(ref state.RunStartedTimestamp) is var startedAt and not 0) + { + var running = Stopwatch.GetElapsedTime(startedAt); + var threshold = timeout * _stuckFactor; + if (running > threshold) + { + Quarantine(key, state, + $"its previous evaluation has been running for {running.TotalSeconds:F1} s, over " + + $"{_stuckFactor:0.##}x its {timeout.TotalMilliseconds:F0} ms budget " + + "(Scripting:StuckOrphanQuarantineFactor) — it is stuck; the script is not evaluated again " + + "until its source changes or it is redeployed", + "stuck"); + throw new ScriptQuarantinedException(key, state.QuarantineReason!); + } + } + throw new ScriptRunRefusedException(key); + } + + Interlocked.Increment(ref _inFlight); + Interlocked.Increment(ref _started); + + var slot = new RunSlot(); + var started = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var runCts = CancellationTokenSource.CreateLinkedTokenSource(ct); + var runToken = runCts.Token; + + // Task.Run deliberately takes NO token: a pre-cancelled token would skip the lambda, `started` would + // never complete, and the slot would never be released. The evaluator observes the token instead. + var runTask = Task.Run(async () => + { + Volatile.Write(ref state.RunStartedTimestamp, Stopwatch.GetTimestamp()); + started.TrySetResult(); + var before = GC.GetAllocatedBytesForCurrentThread(); + try + { + // ScriptEvaluator.RunAsync executes the compiled delegate synchronously and returns a completed + // task, so the after-sample is taken on the same thread, right after the script returned. + var pending = evaluator.RunAsync(context, runToken); + slot.AllocatedBytes = GC.GetAllocatedBytesForCurrentThread() - before; + return await pending.ConfigureAwait(false); + } + catch + { + slot.AllocatedBytes = GC.GetAllocatedBytesForCurrentThread() - before; + throw; + } + }); + + // Release the slot when the run REALLY finishes — which for an abandoned run is long after this + // method has thrown ScriptTimeoutException. Registered before the wait so it fires regardless of + // which way the wait below comes out. A late-finishing orphan that breached the allocation budget + // still quarantines its key here. + _ = runTask.ContinueWith(t => + { + Volatile.Write(ref state.RunStartedTimestamp, 0); + Interlocked.Exchange(ref state.InFlight, 0); + Interlocked.Decrement(ref _inFlight); + runCts.Dispose(); + if (t.IsFaulted) _ = t.Exception; // observed below by the awaiter when it is still listening + if (t.IsCompletedSuccessfully && BreachedBudget(slot.AllocatedBytes)) + Quarantine(key, state, AllocationReason(slot.AllocatedBytes), "allocation"); + }, CancellationToken.None, TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default); + + // The budget clock starts when the pool starts the run, not when we queued it (P5): pool starvation + // is a host problem and must not be reported as "script timed out". + await started.Task.WaitAsync(ct).ConfigureAwait(false); + + TResult result; + try + { + result = await runTask.WaitAsync(timeout, ct).ConfigureAwait(false); + } + catch (TimeoutException) + { + // The caller's cancel wins even when it lands a few µs after the timeout fired. + if (ct.IsCancellationRequested) throw new OperationCanceledException(ct); + runCts.Cancel(); + if (NoteTimeout(key, state, timeout)) + throw new ScriptQuarantinedException(key, state.QuarantineReason!); + throw new ScriptTimeoutException(timeout); + } + catch (OperationCanceledException) when (ct.IsCancellationRequested) + { + throw; + } + catch (Exception) + { + // The script returned control (by throwing) — that is a completion for quarantine purposes. + Interlocked.Exchange(ref state.ConsecutiveTimeouts, 0); + throw; + } + + Interlocked.Exchange(ref state.ConsecutiveTimeouts, 0); + if (BreachedBudget(slot.AllocatedBytes)) + { + // The continuation above has already (or will have) quarantined the key; make the reason visible + // to THIS caller too, so the breaching run itself publishes Bad rather than a suspect value. + Quarantine(key, state, AllocationReason(slot.AllocatedBytes), "allocation"); + throw new ScriptQuarantinedException(key, state.QuarantineReason!); + } + return result; + } + + /// Resolve the key's state, rolling it over when the source identity changed, and refuse a quarantined key. + private KeyState Admit(string key, string? sourceIdentity) + { + while (true) + { + var state = _keys.GetOrAdd(key, static (_, src) => new KeyState(src), sourceIdentity); + if (sourceIdentity is not null && state.SourceIdentity is not null + && !string.Equals(state.SourceIdentity, sourceIdentity, StringComparison.Ordinal)) + { + // The script changed under this key: start from a clean slate. The old state's orphan (if any) + // releases the GLOBAL in-flight count through its own continuation; nothing else references it. + _keys.TryUpdate(key, new KeyState(sourceIdentity), state); + continue; + } + if (sourceIdentity is not null && state.SourceIdentity is null) + { + state.SourceIdentity = sourceIdentity; + } + if (state.QuarantineReason is { } reason) + throw new ScriptQuarantinedException(key, reason); + return state; + } + } + + /// Record a timeout strike; returns true when it tipped the key into quarantine. A completed run + /// (value or throw) resets the streak; a refusal neither counts nor resets. + private bool NoteTimeout(string key, KeyState state, TimeSpan timeout) + { + var count = Interlocked.Increment(ref state.ConsecutiveTimeouts); + if (count < _quarantineThreshold) return false; + Quarantine(key, state, + $"{count} consecutive evaluation(s) timed out (budget {timeout.TotalMilliseconds:F0} ms); " + + "the script is not evaluated again until its source changes or it is redeployed", + "timeouts"); + return true; + } + + private bool BreachedBudget(long allocatedBytes) => + _maxAllocBytesPerRun > 0 && allocatedBytes > _maxAllocBytesPerRun; + + private string AllocationReason(long allocatedBytes) => + $"one evaluation allocated {allocatedBytes / (1024.0 * 1024.0):F1} MB, over the " + + $"{_maxAllocBytesPerRun / (1024.0 * 1024.0):F0} MB budget (Scripting:MaxAllocBytesPerRun); " + + "the script is not evaluated again until its source changes or it is redeployed"; + + private void Quarantine(string key, KeyState state, string why, string metricReason) + { + var reason = QuarantinedReasonPrefix + why; + // First writer wins: a late orphan and the awaiter can both reach here for the same run. + if (Interlocked.CompareExchange(ref state.QuarantineReason, reason, null) is not null) return; + + Interlocked.Increment(ref _quarantined); + QuarantinedCounter.Add(1, + new KeyValuePair("script", key), + new KeyValuePair("reason", metricReason)); + _logger.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); + } + } + + private sealed class KeyState(string? sourceIdentity) + { + public string? SourceIdentity = sourceIdentity; + public int InFlight; + public int ConsecutiveTimeouts; + /// when the pool started the in-flight run; 0 when idle. + public long RunStartedTimestamp; + public string? QuarantineReason; + } + + private sealed class RunSlot + { + public long AllocatedBytes; + } +} + +/// Carried by . +/// The quarantined script instance key. +/// Why, prefixed . +public sealed record ScriptQuarantinedEventArgs(string Key, string Reason); + +/// +/// Thrown by when the script's previous run is +/// still executing (an abandoned, timed-out run that never returned). Nothing was dispatched; the seam +/// publishes Bad with . +/// +public sealed class ScriptRunRefusedException : Exception +{ + /// The script instance key. + public string Key { get; } + + /// Initializes the exception for . + /// The script instance key. + public ScriptRunRefusedException(string key) : base(ScriptRunGuard.PreviousRunStillRunningReason) + { + Key = key; + } +} + +/// +/// Thrown by for a quarantined script: repeated +/// timeouts, a stuck orphan or an allocation-budget breach. Nothing is dispatched while quarantined; the seam +/// publishes Bad carrying the reason, which an operator clears by fixing the script (source change) or +/// redeploying. +/// +public sealed class ScriptQuarantinedException : Exception +{ + /// The script instance key. + public string Key { get; } + + /// Initializes the exception with the quarantine reason (already prefixed). + /// The script instance key. + /// The quarantine reason, prefixed . + public ScriptQuarantinedException(string key, string reason) : base(reason) + { + Key = key; + } +} diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptingOptions.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptingOptions.cs new file mode 100644 index 00000000..296d862c --- /dev/null +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptingOptions.cs @@ -0,0 +1,56 @@ +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; + +/// +/// Node-wide script runtime-safety knobs (the Scripting appsettings section), consumed by +/// . One instance is shared by every script seam on the node — the +/// virtual-tag evaluator, the Calculation evaluator and the scripted-alarm engine — so a single setting +/// bounds every authored script the same way. +/// +/// +/// +/// The in-process sandbox cannot pre-empt a script: a while(true) is abandoned on its pool +/// thread at the timeout, and an allocation is observed only after the run returns. These knobs bound +/// the damage — one orphan per script, no further runs until the source changes — not the +/// first occurrence. Pre-emptive CPU/memory budgeting needs an out-of-process script runner. +/// +/// +public sealed class ScriptingOptions +{ + /// The appsettings section this binds from. + public const string SectionName = "Scripting"; + + /// Default : 64 MB. + public const long DefaultMaxAllocBytesPerRun = 64L * 1024 * 1024; + + /// Default : 3. + public const int DefaultQuarantineAfterConsecutiveTimeouts = 3; + + /// Default : 10. + public const double DefaultStuckOrphanQuarantineFactor = 10; + + /// + /// Managed bytes one script run may allocate on its own thread (sampled with + /// around the run) before the script is + /// quarantined. Zero or negative disables the budget. Default 64 MB. + /// + public long MaxAllocBytesPerRun { get; set; } = DefaultMaxAllocBytesPerRun; + + /// + /// Consecutive timeouts after which the script is quarantined: no further runs are dispatched, every + /// evaluation reports Bad, and the quarantine lifts only on a source change, a redeploy or an explicit + /// reset. Only a timeout is a strike — a run refused because the previous one is still executing is + /// reported Bad and counted, but neither adds to nor resets the streak; a completed run (value or + /// throw) resets it. Default 3; values below 1 are treated as 1. + /// + public int QuarantineAfterConsecutiveTimeouts { get; set; } = DefaultQuarantineAfterConsecutiveTimeouts; + + /// + /// A refusal quarantines the script immediately when the abandoned run it was refused behind has been + /// executing for longer than this many times the script's timeout (20 s at the 2 s default). This is + /// what quarantines a permanently stuck script (while(true)): it times out once and is then + /// only ever refused, so the timeout streak alone would never reach + /// . A young orphan (a short overrun) is still just a + /// refusal. Zero or negative disables the rule. Default 10. + /// + public double StuckOrphanQuarantineFactor { get; set; } = DefaultStuckOrphanQuarantineFactor; +} diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/TimedScriptEvaluator.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/TimedScriptEvaluator.cs index 4adeccab..7a860436 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/TimedScriptEvaluator.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/TimedScriptEvaluator.cs @@ -19,10 +19,12 @@ namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; /// task continues running on a thread-pool thread until the Roslyn runtime /// returns. In the CPU-bound-infinite-loop case that's effectively "leaked" — /// the thread is tied up until the runtime decides to return, which it may -/// never do. Phase 7 plan Stream A.4 accepts this as a known trade-off; tighter -/// CPU budgeting would require an out-of-process script runner, which is a v3 -/// concern. In practice, the timeout + structured warning log surfaces the -/// offending script so the operator can fix it; the orphan thread is rare. +/// never do. This wrapper has no memory of that orphan, so re-running the same +/// script through it on every trigger leaks one more thread per trigger — which +/// is why the production seams (virtual tags, Calculation, scripted alarms) run +/// through instead: same timeout, plus a per-script +/// "previous run still executing" refusal and a quarantine. This class remains +/// for callers that evaluate once (tests, the authoring preview). /// /// /// Caller-supplied is honored — if the caller diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriver.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriver.cs index d556ccf6..9f8ef41b 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriver.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriver.cs @@ -92,7 +92,15 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba // the timer ticks — the mutual exclusion _lock used to provide while it was held across the run, minus // the blocking. Taken ONLY by evaluation workers, so no host thread (mux callback, ReadAsync, // reinit) can ever wait on a script. Lock order is always _evalGate → _lock, never the reverse. - private readonly object _evalGate = new(); + // A SemaphoreSlim rather than a monitor because the holder AWAITS the script run (the pump is async — + // it no longer parks a second pool thread behind the one the script runs on, and the run-guard's + // budget clock starts only once the pool has picked the script up, so pool starvation is never + // reported as a script timeout). + private readonly SemaphoreSlim _evalGate = new(1, 1); + + // Cancels an awaited script run on Dispose (the only hard teardown — ShutdownAsync leaves an in-flight + // run to its RunTimeout, exactly as before, since the pump drops its result once _running is false). + private readonly CancellationTokenSource _evalCts = new(); // Change-triggered evaluations queued by OnDependencyValue and drained, in arrival order, by a single // pump task. Both fields are guarded by _lock; _pumpScheduled stays true until the pump observes an @@ -103,7 +111,7 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba private CalculationTimerScheduler? _timers; private volatile bool _running; private DateTime? _lastComputeUtc; - private bool _disposed; + private volatile bool _disposed; /// Occurs when a calc tag's computed value changes (or transitions Good↔Bad). public event EventHandler? OnDataChange; @@ -129,7 +137,7 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba // _logger (ILogger) implements the non-generic ILogger, so it is passed straight // through — the evaluator's host-side diagnostics (compile errors, sandbox violations, execution // throws) land on the SAME logger the driver itself was constructed with, not a separate one. - _evaluator = new CalculationEvaluator(_logger, _scriptRoot, _options.RunTimeout); + _evaluator = new CalculationEvaluator(_logger, _scriptRoot, _options.RunTimeout, _options.Scripting); RebuildTagTable(_options); } @@ -225,6 +233,7 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba { RawTags = dto.RawTags is { Count: > 0 } ? [.. dto.RawTags] : [], RunTimeout = _options.RunTimeout, + Scripting = _options.Scripting, }; } } @@ -235,7 +244,10 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba _driverInstanceId); } } - return new CalculationDriverOptions { RawTags = _options.RawTags, RunTimeout = _options.RunTimeout }; + return new CalculationDriverOptions + { + RawTags = _options.RawTags, RunTimeout = _options.RunTimeout, Scripting = _options.Scripting, + }; } /// Re-bind the tag table from — shared by @@ -326,6 +338,11 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba StopTimers(); // The pump exits at its next iteration; an evaluation already in flight is bounded by RunTimeout. lock (_lock) _pending.Clear(); + // R07:L2 — nothing in the runtime disposes a driver, and every config change is a respawn, so + // the compiled scripts' collectible ALCs survived each generation until GC got round to the whole + // driver graph. Drop them here (idempotent; a later InitializeAsync recompiles on first use). An + // in-flight run that races this is already handled by the evaluator's retry-once path. + _evaluator.ClearCompiledScripts(); return Task.CompletedTask; } @@ -351,11 +368,15 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba /// public void OnDependencyValue(string rawPath, object? value, uint statusCode, DateTime timestampUtc) { - if (!_running) return; lock (_lock) { + // Recorded REGARDLESS of _running (R07:H6): the mux adapter registers interest at construction, + // so inputs — the mux's retained-value replay in particular — can land before InitializeAsync. + // Dropping them left every calc tag waiting for each input to change again; keeping them means + // the first trigger after init evaluates from current inputs. Only the EVALUATION is gated. _depValues[rawPath] = new DataValueSnapshot(value, statusCode, timestampUtc, timestampUtc); _arrivedDeps.Add(rawPath); + if (!_running) return; if (!_changeDependents.TryGetValue(rawPath, out var dependents) || dependents.Count == 0) return; // QUEUE each change-triggered dependent — never evaluate here. This @@ -491,13 +512,15 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba { if (_pumpScheduled) return; _pumpScheduled = true; - _ = Task.Run(RunEvaluationPump); + _ = Task.Run(RunEvaluationPumpAsync); } - /// Drain the queued change-triggered evaluations, in arrival order, on a pool thread. At most - /// one pump runs at a time, so per-tag evaluation ordering is preserved exactly as it was when the - /// change path evaluated inline under the state lock. - private void RunEvaluationPump() + /// Drain the queued change-triggered evaluations, in arrival order. At most one pump runs at a + /// time, so per-tag evaluation ordering is preserved exactly as it was when the change path evaluated + /// inline under the state lock. Async: the pump AWAITS each script run instead of parking a pool thread + /// behind the one the script executes on (P5 — sync-over-async with a nested Task.Run manufactured + /// false timeouts under pool starvation). + private async Task RunEvaluationPumpAsync() { while (true) { @@ -515,39 +538,69 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba // _evalGate (never _lock) is held across the run, so the pump and the timer ticks still // evaluate one at a time while no host thread can block behind a script. - lock (_evalGate) + if (!await TryEnterEvalGateAsync().ConfigureAwait(false)) return; // disposed + try { - try - { - RunEvaluation(next); - } - catch (Exception ex) - { - // The evaluator never throws for script faults, so this is a defect path only — it - // must not kill the pump and strand every queued evaluation behind it. - _logger.LogError(ex, "Calculation {Driver}: evaluation of {RawPath} failed", - _driverInstanceId, next.Definition.RawPath); - } + await RunEvaluationAsync(next).ConfigureAwait(false); + } + catch (Exception ex) + { + // The evaluator never throws for script faults, so this is a defect path only — it + // must not kill the pump and strand every queued evaluation behind it. + _logger.LogError(ex, "Calculation {Driver}: evaluation of {RawPath} failed", + _driverInstanceId, next.Definition.RawPath); + } + finally + { + _evalGate.Release(); } } } - /// Timer-trigger entry point — prepares and evaluates a single calc tag on the scheduler's - /// pool thread (the scheduler's per-group in-flight guard is what bounds outstanding timer work). - private void EvaluateTagFromTimer(string rawPath) + /// Timer-trigger entry point — prepares and evaluates a single calc tag (the scheduler's + /// per-group in-flight guard is what bounds outstanding timer work; it stays set until this task + /// completes). + private async Task EvaluateTagFromTimerAsync(string rawPath) { if (!_running) return; PendingEvaluation? prepared; lock (_lock) prepared = PrepareEvaluation(rawPath, DateTime.UtcNow); if (prepared is null) return; - lock (_evalGate) RunEvaluation(prepared); + if (!await TryEnterEvalGateAsync().ConfigureAwait(false)) return; // disposed + try + { + await RunEvaluationAsync(prepared).ConfigureAwait(false); + } + finally + { + _evalGate.Release(); + } + } + + /// Acquire ; false once has disposed it (a pump + /// iteration or timer tick that raced the teardown simply stops). + private async Task TryEnterEvalGateAsync() + { + if (_disposed) return false; + try + { + await _evalGate.WaitAsync().ConfigureAwait(false); + } + catch (ObjectDisposedException) + { + return false; + } + if (!_disposed) return true; + // Dispose landed while we waited (it gave up the gate without disposing it): back out. + _evalGate.Release(); + return false; } /// Run one prepared evaluation and publish the outcome. MUST be called under /// and NOT under : the script run is the whole point of the /// split, and the script log + fan-out both invoke subscriber code. /// The prepared evaluation. - private void RunEvaluation(PendingEvaluation pending) + private async Task RunEvaluationAsync(PendingEvaluation pending) { var def = pending.Definition; @@ -572,9 +625,10 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba // Snapshots, not bare values: the script's ctx.GetTag(path).StatusCode / .SourceTimestampUtc are // then the input's real ones rather than a fabricated Good stamped at evaluation time. - var result = _evaluator.Evaluate(def.RawPath, def.ScriptSource, pending.Dependencies); + var result = await _evaluator.EvaluateAsync(def.RawPath, def.ScriptSource, pending.Dependencies, _evalCts.Token) + .ConfigureAwait(false); - string? failureReason = null; + string? failureToLog = null; (object? Value, uint StatusCode)? toPublish; lock (_lock) { @@ -584,16 +638,24 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba if (!result.Success) { - failureReason = result.Reason ?? "evaluator failure"; + var reason = result.Reason ?? "evaluator failure"; toPublish = MarkEvaluationFailed(st, pending.TimestampUtc); + // The script-log entry fires on the Good→Bad TRANSITION, or when the failure changes + // (R07:P4) — not on every trigger of a tag that is already Bad for the same reason, which + // flooded the script log at the input's cadence. The Bad publish was already once per + // transition; the log now matches it. + if (toPublish is not null || !string.Equals(st.LastFailureReason, reason, StringComparison.Ordinal)) + failureToLog = reason; + st.LastFailureReason = reason; } else { + st.LastFailureReason = null; toPublish = MarkEvaluationSucceeded(st, result.Value, pending.WorstInputStatus, pending.TimestampUtc); } } - if (failureReason is not null) PublishScriptLog(def, failureReason); + if (failureToLog is not null) PublishScriptLog(def, failureToLog); if (toPublish is { } p) Publish(def.RawPath, p.Value, p.StatusCode, pending.TimestampUtc); } @@ -612,7 +674,7 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba private (object? Value, uint StatusCode)? MarkEvaluationSucceeded( TagState st, object? value, uint statusCode, DateTime timestampUtc) { - if (st.HasPublished && st.LastPublishedStatus == statusCode && st.HasValue && Equals(st.LastValue, value)) + if (st.HasPublished && st.LastPublishedStatus == statusCode && st.HasValue && ValuesEqual(st.LastValue, value)) return null; st.HasValue = true; @@ -624,6 +686,17 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba return (value, statusCode); } + /// Value equality for the dedup: structural for arrays (R07:H8 — object.Equals is reference + /// equality for a double[], so an array-returning timer script republished every tick through + /// the dual-namespace fan-out and the historian), ordinary + /// otherwise. + private static bool ValuesEqual(object? a, object? b) + { + if (a is Array x && b is Array y) + return System.Collections.StructuralComparisons.StructuralEqualityComparer.Equals(x, y); + return Equals(a, b); + } + /// Record that this tag's INPUTS are Bad, so no evaluation ran. Publishes the /// worst input's status — carrying the last known value — once per change of that status: a /// repeat of the same Bad is silent, while BadNoCommunication arriving over an earlier @@ -688,7 +761,7 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba { var timed = _tagsByRawPath.Values.Where(t => t.TimerInterval is not null).ToArray(); if (timed.Length == 0) return; - _timers = new CalculationTimerScheduler(EvaluateTagFromTimer, _logger); + _timers = new CalculationTimerScheduler(EvaluateTagFromTimerAsync, _logger); _timers.Start(timed); } @@ -701,6 +774,12 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba /// Test/diagnostic accessor: number of timer ticks skipped for in-flight groups. internal long TimerSkippedTickCount => _timers?.SkippedTickCount ?? 0; + /// Test/diagnostic accessor: sources currently remembered as failing to compile. + internal int CompileFailureCountForTest => _evaluator.CompileFailureCount; + + /// Test/diagnostic accessor: compiled scripts currently held by the evaluator's cache. + internal int CompiledScriptCountForTest => _evaluator.CompiledScriptCount; + /// Test/diagnostic accessor: when no change-triggered evaluation is /// queued or in flight. A test that used to assert straight after — /// which evaluated inline — waits on this instead, so the assertion still runs against a settled @@ -723,9 +802,34 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba _running = false; StopTimers(); lock (_lock) _pending.Clear(); + // Cancel an awaited run first (the guard lets the caller's cancel win over the timeout), then drop + // the compiled scripts. + try { _evalCts.Cancel(); } catch (ObjectDisposedException) { } _evaluator.Dispose(); + + // Then take the gate: once Dispose holds it no evaluation is mid-run (the token — read only under + // the gate — has been observed), so the gate and the CTS can be disposed. A late pump iteration or + // timer tick sees _disposed / an ObjectDisposedException in TryEnterEvalGateAsync and stops. Bounded: + // a run that ignores the cancel cannot hold Dispose; in that case both are left to the GC. + if (_evalGate.Wait(DisposeGateTimeout)) + { + _evalCts.Dispose(); + _evalGate.Dispose(); + _evalResourcesDisposed = true; + } + else + { + _logger.LogWarning("Calculation {Driver}: an evaluation did not release the gate within {Timeout} of Dispose; leaving it to the GC", + _driverInstanceId, DisposeGateTimeout); + } } + private static readonly TimeSpan DisposeGateTimeout = TimeSpan.FromSeconds(2); + private volatile bool _evalResourcesDisposed; + + /// Test hook — whether disposed the evaluation gate and its CTS. + internal bool EvalResourcesDisposedForTest => _evalResourcesDisposed; + /// Per-tag published state (guarded by ). private sealed class TagState { @@ -741,6 +845,10 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba /// now carries the failing INPUT's sub-code rather than a fixed BadInternalError. public uint LastPublishedStatus; public DateTime LastTimestampUtc; + + /// The reason of the last failed evaluation (null after a success / inputs-Bad hold) — the + /// gate that keeps the script-log entry to the transition and to a CHANGE of reason. + public string? LastFailureReason; } private sealed record CalculationSubscriptionHandle(string DiagnosticId) : ISubscriptionHandle; diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriverFactoryExtensions.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriverFactoryExtensions.cs index ab10f06d..1a589d65 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriverFactoryExtensions.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriverFactoryExtensions.cs @@ -71,11 +71,22 @@ public static class CalculationDriverFactoryExtensions ?? throw new InvalidOperationException( $"Calculation driver config for '{driverInstanceId}' deserialised to null"); + // Run-guard knobs are optional and default to the node-wide ScriptingOptions defaults; only an + // explicitly authored key overrides one (so a config carrying neither binds Scripting = null). + ScriptingOptions? scripting = null; + if (dto.MaxAllocBytesPerRun is not null || dto.QuarantineAfterConsecutiveTimeouts is not null) + { + scripting = new ScriptingOptions(); + if (dto.MaxAllocBytesPerRun is { } alloc) scripting.MaxAllocBytesPerRun = alloc; + if (dto.QuarantineAfterConsecutiveTimeouts is { } n) scripting.QuarantineAfterConsecutiveTimeouts = n; + } + var options = new CalculationDriverOptions { RawTags = dto.RawTags is { Count: > 0 } ? [.. dto.RawTags] : [], RunTimeout = dto.RunTimeoutMs is { } ms && ms > 0 ? TimeSpan.FromMilliseconds(ms) : TimeSpan.FromSeconds(2), + Scripting = scripting, }; return new CalculationDriver( @@ -92,5 +103,11 @@ public static class CalculationDriverFactoryExtensions /// Optional per-script evaluation wall-clock budget override, in milliseconds (default 2000). public int? RunTimeoutMs { get; init; } + + /// Optional run-guard allocation budget per script run, in bytes (default 64 MB; ≤ 0 disables). + public long? MaxAllocBytesPerRun { get; init; } + + /// Optional run-guard quarantine threshold: consecutive timeouts (refusals do not count) before a tag's script stops being evaluated (default 3). + public int? QuarantineAfterConsecutiveTimeouts { get; init; } } } diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriverOptions.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriverOptions.cs index b6642c09..f00f50e4 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriverOptions.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriverOptions.cs @@ -1,20 +1,21 @@ using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; namespace ZB.MOM.WW.OtOpcUa.Driver.Calculation; -/// -/// Bound options for a instance. The Calculation pseudo-driver has -/// no backend/endpoint config — its only input is the authored raw calc tags the deploy artifact -/// injects as the list (each carrying the tag's scriptId + resolved -/// scriptSource + trigger config inside its blob). -/// +/// Bound options for one instance. public sealed class CalculationDriverOptions { - /// The driver's authored raw calc tags (RawPath + TagConfig blob + WriteIdempotent), from - /// the deploy artifact. Each is mapped to a at construction. + /// The authored raw calc tags (RawPath + TagConfig JSON) this driver computes. public IReadOnlyList RawTags { get; init; } = Array.Empty(); - /// Per-script wall-clock evaluation budget handed to the . - /// Defaults to 2 seconds (parity with the VirtualTag evaluator). + /// Wall-clock budget per script run (driver-config runTimeoutMs); default 2 s. public TimeSpan RunTimeout { get; init; } = TimeSpan.FromSeconds(2); + + /// + /// Run-guard budget + quarantine threshold for this driver's scripts (driver-config + /// maxAllocBytesPerRun / quarantineAfterConsecutiveTimeouts). Null ⇒ the + /// defaults (64 MB, 3). + /// + public ScriptingOptions? Scripting { get; init; } } diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs index 249c6958..dd7085e3 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs @@ -1,3 +1,4 @@ +using System.Collections.Concurrent; using Microsoft.Extensions.Logging; using ZB.MOM.WW.OtOpcUa.Commons.Engines; using ZB.MOM.WW.OtOpcUa.Core.Abstractions; @@ -37,8 +38,18 @@ namespace ZB.MOM.WW.OtOpcUa.Driver.Calculation; /// apply-boundary clear, which is what stops collectible AssemblyLoadContexts accreting across /// script edits. /// +/// +/// Run quarantine. Every compiled run goes through one keyed by +/// calc-tag RawPath with the script source as the identity: a run is refused while the tag's previous +/// (timed-out, abandoned) run is still executing, and the tag is quarantined after three consecutive +/// timeouts (a refusal is Bad but not a strike, unless its orphan is stuck past StuckOrphanQuarantineFactor × the budget) or an allocation-budget breach — both surface as a +/// the driver maps to Bad. The driver's evaluation pump awaits rather than +/// blocking a pool thread on the sync , +/// and the guard starts the budget clock only once the pool has picked the script up, so pool starvation +/// is never reported as a script timeout. +/// /// -public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable +public sealed class CalculationEvaluator : IScriptCacheOwner, IScriptQuarantineOwner, IDisposable { // Source-hash-keyed compile cache: Lazy single-compile (no double-compile race) and Clear()/Dispose() // that dispose each evaluator's collectible AssemblyLoadContext. ClearCompiledScripts() — driven by the @@ -47,6 +58,14 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable private readonly ILogger _logger; private readonly SerilogLogger _scriptRoot; private readonly TimeSpan _runTimeout; + private readonly ScriptRunGuard _guard; + + // Negative compile cache (R07:P4), keyed by source hash. A compile error is a property of the SOURCE, + // which never changes between triggers (it is fixed in the deploy artifact) — yet every trigger of a + // broken tag used to re-run a full Roslyn compile under the driver-wide evaluation gate, starving the + // healthy tags behind it, and log the same Warning each time. The failure is now remembered until the + // next ClearCompiledScripts (a redeploy), and the host Warning fires once per source. + private readonly ConcurrentDictionary _compileFailures = new(StringComparer.Ordinal); private bool _disposed; /// Initializes a new . @@ -56,16 +75,22 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable /// implements this — instead of needing a second, separately-obtained logger instance. /// Root script logger; user ctx.Logger.* output flows through this to the Script-log page. /// Wall-clock budget per script run; defaults to 2 seconds (parity with the VT evaluator). + /// Run-guard budget + quarantine threshold; null ⇒ defaults. public CalculationEvaluator( ILogger logger, ScriptRootLogger scriptRoot, - TimeSpan? runTimeout = null) + TimeSpan? runTimeout = null, + ScriptingOptions? scripting = null) { _logger = logger ?? throw new ArgumentNullException(nameof(logger)); _scriptRoot = (scriptRoot ?? throw new ArgumentNullException(nameof(scriptRoot))).Logger; _runTimeout = runTimeout ?? TimeSpan.FromSeconds(2); + _guard = new ScriptRunGuard(scripting, _scriptRoot); } + /// The run guard every compiled evaluation goes through (diagnostics / tests). + public ScriptRunGuard RunGuard => _guard; + /// /// Evaluate for the calc tag against /// the snapshot in (RawPath → last value). Never throws — script @@ -112,8 +137,25 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable /// The C# script source producing the tag's value. /// Read-only snapshot of dependency values keyed by RawPath. /// The evaluation outcome. + /// Blocks the calling thread for the run. The driver's pump uses ; + /// this overload remains for callers with no async context — chiefly tests. public VirtualTagEvalResult Evaluate( string calcTagId, string scriptSource, IReadOnlyDictionary dependencies) + => EvaluateAsync(calcTagId, scriptSource, dependencies).GetAwaiter().GetResult(); + + /// + /// The async form of : + /// the compiled script runs on the pool under the and the caller awaits + /// it instead of blocking a second pool thread for the duration. Never throws for script faults. + /// + /// Identity of the calc tag (bound to the script log). + /// The C# script source producing the tag's value. + /// Read-only snapshot of dependency values keyed by RawPath. + /// Caller cancellation (driver shutdown); wins over the run timeout. + /// The evaluation outcome. + public async Task EvaluateAsync( + string calcTagId, string scriptSource, IReadOnlyDictionary dependencies, + CancellationToken ct = default) { if (_disposed) return VirtualTagEvalResult.Failure("evaluator disposed"); if (string.IsNullOrWhiteSpace(scriptSource)) return VirtualTagEvalResult.Failure("empty expression"); @@ -146,6 +188,11 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable calcTagId, path), logger: scriptLog); + // A source that already failed to compile fails the same way without touching Roslyn (R07:P4). + var sourceKey = HashSource(scriptSource); + if (_compileFailures.TryGetValue(sourceKey, out var knownFailure)) + return VirtualTagEvalResult.Failure(knownFailure); + // Fetch + run inside a bounded loop so an ObjectDisposedException caused by a concurrent // ClearCompiledScripts (which disposed the evaluator between GetOrCompile and the run's // disposed guard) re-fetches and retries exactly once. The loop runs at most twice. @@ -158,13 +205,11 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable } catch (CompilationErrorException ex) { - _logger.LogWarning(ex, "Calculation {Id}: Roslyn compile failed", calcTagId); - return VirtualTagEvalResult.Failure($"compile error: {ex.Message}"); + return RememberCompileFailure(sourceKey, calcTagId, $"compile error: {ex.Message}", ex, "Roslyn compile failed"); } catch (ScriptSandboxViolationException ex) { - _logger.LogWarning(ex, "Calculation {Id}: sandbox violation", calcTagId); - return VirtualTagEvalResult.Failure($"sandbox violation: {ex.Message}"); + return RememberCompileFailure(sourceKey, calcTagId, $"sandbox violation: {ex.Message}", ex, "sandbox violation"); } catch (ObjectDisposedException) { @@ -180,11 +225,12 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable try { - // Route through TimedScriptEvaluator (Task.Run + WaitAsync): a raw CancellationToken can't - // interrupt a CPU-bound/infinite-loop Roslyn script, so the timed wrapper is what bounds a - // runaway script to the wall-clock budget instead of wedging the driver's dispatch. - var timed = new TimedScriptEvaluator(evaluator, _runTimeout); - var raw = timed.RunAsync(context).GetAwaiter().GetResult(); + // Route through the ScriptRunGuard (Task.Run + WaitAsync, keyed by RawPath): a raw + // CancellationToken can't interrupt a CPU-bound/infinite-loop Roslyn script, so the wall-clock + // budget is what bounds a runaway script — and the guard is what keeps the next trigger from + // stacking another orphan behind it (one per tag, then quarantine). + var raw = await _guard.RunAsync(calcTagId, scriptSource, evaluator, context, _runTimeout, ct) + .ConfigureAwait(false); return VirtualTagEvalResult.Ok(raw); } catch (ScriptTimeoutException) @@ -192,6 +238,18 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable return VirtualTagEvalResult.Failure( $"{ScriptEvalFailureReasons.TimedOutPrefix}{_runTimeout.TotalSeconds:F1}s"); } + catch (ScriptRunRefusedException ex) + { + return VirtualTagEvalResult.Failure(ex.Message); + } + catch (ScriptQuarantinedException ex) + { + return VirtualTagEvalResult.Failure(ex.Message); + } + catch (OperationCanceledException) when (ct.IsCancellationRequested) + { + return VirtualTagEvalResult.Failure("evaluation cancelled (driver shutting down)"); + } catch (ObjectDisposedException) when (!_disposed && attempt == 0) { // A concurrent ClearCompiledScripts disposed the evaluator between our GetOrCompile and the @@ -211,8 +269,39 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable } } + /// Record a compile failure for and log it ONCE — the next trigger + /// of the same source returns the remembered reason without a Roslyn round-trip or a second Warning. + private VirtualTagEvalResult RememberCompileFailure(string sourceKey, string calcTagId, string reason, Exception ex, string what) + { + if (_compileFailures.TryAdd(sourceKey, reason)) + _logger.LogWarning(ex, "Calculation {Id}: {What} (remembered until the next redeploy)", calcTagId, what); + return VirtualTagEvalResult.Failure(reason); + } + + private static string HashSource(string source) + => Convert.ToHexString(System.Security.Cryptography.SHA256.HashData(System.Text.Encoding.UTF8.GetBytes(source))); + + /// Test/diagnostic: the number of sources currently remembered as failing to compile. + public int CompileFailureCount => _compileFailures.Count; + + /// Test/diagnostic: the number of compiled scripts currently cached. + public int CompiledScriptCount => _cache.Count; + /// - public void ClearCompiledScripts() => _cache.Clear(); + public void ClearCompiledScripts() + { + _cache.Clear(); + _compileFailures.Clear(); + // The compile-cache clear is this evaluator's deploy boundary — a redeploy lifts every quarantine + // (an edited source already lifts its own through the guard's source identity). + _guard.ResetAll(); + } + + /// + public void ResetQuarantines() => _guard.ResetAll(); + + /// + public IReadOnlyCollection QuarantinedScripts => _guard.QuarantinedKeys; /// Disposes the evaluator, draining + disposing every cached compile's collectible ALC. public void Dispose() @@ -220,5 +309,6 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable if (_disposed) return; _disposed = true; _cache.Dispose(); + _compileFailures.Clear(); } } diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationTimerScheduler.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationTimerScheduler.cs index ef74da0e..694f7d8a 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationTimerScheduler.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationTimerScheduler.cs @@ -7,11 +7,13 @@ namespace ZB.MOM.WW.OtOpcUa.Driver.Calculation; /// per distinct interval group (so the wire count stays low /// regardless of tag count) with a per-group in-flight flag that skips a tick when the prior tick for /// the same group is still running. Each tick invokes the driver's own evaluate -/// callback per tag in the group. +/// callback per tag in the group and AWAITS it — the in-flight flag is held across the awaited script +/// run, not just across the synchronous part of the callback, so a slow script still bounds its group +/// to one outstanding tick. /// internal sealed class CalculationTimerScheduler : IDisposable { - private readonly Action _evaluate; + private readonly Func _evaluate; private readonly ILogger _logger; private readonly List _timers = []; private readonly List _groups = []; @@ -20,9 +22,9 @@ internal sealed class CalculationTimerScheduler : IDisposable private bool _disposed; /// Initializes a new instance of the class. - /// Callback invoked with a calc tag's RawPath when its timer group ticks. + /// Callback invoked with a calc tag's RawPath when its timer group ticks; awaited. /// Logger for diagnostics. - public CalculationTimerScheduler(Action evaluate, ILogger logger) + public CalculationTimerScheduler(Func evaluate, ILogger logger) { _evaluate = evaluate ?? throw new ArgumentNullException(nameof(evaluate)); _logger = logger ?? throw new ArgumentNullException(nameof(logger)); @@ -69,12 +71,20 @@ internal sealed class CalculationTimerScheduler : IDisposable return; } + // The Timer callback is void; the tick itself is async so the awaited script runs do not pin this + // pool thread. TickAsync owns the in-flight flag and swallows everything — nothing can escape to the + // Timer (which would be an unobserved fault on a timer thread). + _ = TickAsync(ctx); + } + + private async Task TickAsync(TickGroup ctx) + { try { foreach (var path in ctx.Paths) { if (_cts.IsCancellationRequested) return; - try { _evaluate(path); } + try { await _evaluate(path).ConfigureAwait(false); } catch (Exception ex) { _logger.LogError(ex, "CalculationTimerScheduler evaluate failed for {Path}", path); } } } diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs index d77631ea..8a9347d9 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs @@ -31,8 +31,17 @@ namespace ZB.MOM.WW.OtOpcUa.Host.Engines; /// into the fresh cache for one generation; P7's expression-set gate means no-op redeploys no /// longer open this window at all. /// +/// +/// Run quarantine. Every compiled run goes through one keyed by +/// virtual-tag id with the expression as the source identity: a run is refused while the tag's previous +/// (timed-out, abandoned) run is still executing, and the tag is quarantined after three consecutive +/// timeouts (a refusal is Bad but not a strike, unless its orphan is stuck past StuckOrphanQuarantineFactor × the budget) or an allocation-budget breach. Both surface as +/// so VirtualTagActor publishes Bad exactly as it does for a timeout. A quarantine lifts when the +/// expression changes, on / (the deploy +/// boundary), never by itself. +/// /// -public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCacheOwner, IDisposable +public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCacheOwner, IScriptQuarantineOwner, IDisposable { // Purpose-built source-hash-keyed compile cache: Lazy single-compile (no double-compile race) and // Clear()/Dispose() that dispose each evaluator's collectible AssemblyLoadContext. The apply-boundary @@ -42,22 +51,29 @@ public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCac private readonly ILogger _logger; private readonly SerilogLogger _scriptRoot; private readonly TimeSpan _runTimeout; + private readonly ScriptRunGuard _guard; private bool _disposed; /// Initializes a new RoslynVirtualTagEvaluator with the given loggers and optional timeout. /// Logger for recording compilation and execution errors (host diagnostics). /// Root script logger; user ctx.Logger.* output flows through this to the Script-log page. /// Maximum execution time for each script; defaults to 2 seconds if not specified. + /// Run-guard budget + quarantine threshold (the Scripting section); null ⇒ defaults. public RoslynVirtualTagEvaluator( ILogger logger, ScriptRootLogger scriptRoot, - TimeSpan? runTimeout = null) + TimeSpan? runTimeout = null, + ScriptingOptions? scripting = null) { _logger = logger; _scriptRoot = (scriptRoot ?? throw new ArgumentNullException(nameof(scriptRoot))).Logger; _runTimeout = runTimeout ?? TimeSpan.FromSeconds(2); + _guard = new ScriptRunGuard(scripting, _scriptRoot); } + /// The run guard every compiled evaluation goes through (diagnostics / tests). + public ScriptRunGuard RunGuard => _guard; + // Value-only overload. Every dependency reaches the script stamped Good with an // evaluation-time timestamp — bare values carry nothing better. The runtime calls the snapshot // overload instead; this one remains for callers that genuinely hold only @@ -150,13 +166,13 @@ public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCac try { - // Route through TimedScriptEvaluator (Task.Run + WaitAsync): a raw CancellationToken can't - // interrupt a CPU-bound/infinite-loop script (Roslyn scripts don't poll it), so the previous - // CTS-only path let one runaway script hang this actor forever. WaitAsync returns control when - // the wall-clock budget fires regardless of whether the inner task completes (the orphaned - // thread is the documented, accepted trade-off — TimedScriptEvaluator remarks). - var timed = new TimedScriptEvaluator(evaluator, _runTimeout); - var raw = timed.RunAsync(context).GetAwaiter().GetResult(); + // Route through the ScriptRunGuard (Task.Run + WaitAsync, keyed by virtual-tag id): a raw + // CancellationToken can't interrupt a CPU-bound/infinite-loop script (Roslyn scripts don't poll + // it), so the wall-clock budget is what returns control — and the guard is what stops the + // abandoned run from being joined by another on the next trigger (one orphan per tag, then + // quarantine), which is the leak the old per-evaluation TimedScriptEvaluator allowed. + var raw = _guard.RunAsync(virtualTagId, expression, evaluator, context, _runTimeout) + .GetAwaiter().GetResult(); return VirtualTagEvalResult.Ok(raw); } catch (ScriptTimeoutException) @@ -164,6 +180,14 @@ public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCac return VirtualTagEvalResult.Failure( $"{ScriptEvalFailureReasons.TimedOutPrefix}{_runTimeout.TotalSeconds:F1}s"); } + catch (ScriptRunRefusedException ex) + { + return VirtualTagEvalResult.Failure(ex.Message); + } + catch (ScriptQuarantinedException ex) + { + return VirtualTagEvalResult.Failure(ex.Message); + } catch (ObjectDisposedException) when (!_disposed && attempt == 0) { // S12: the apply-boundary ClearCompiledScripts disposed the evaluator between our @@ -185,7 +209,19 @@ public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCac } /// - public void ClearCompiledScripts() => _cache.Clear(); + public void ClearCompiledScripts() + { + _cache.Clear(); + // The compile-cache clear IS the deploy boundary for this evaluator: a redeploy lifts every quarantine + // (an edited expression already lifts its own through the guard's source identity). + _guard.ResetAll(); + } + + /// + public void ResetQuarantines() => _guard.ResetAll(); + + /// + public IReadOnlyCollection QuarantinedScripts => _guard.QuarantinedKeys; /// Disposes the evaluator and cleans up all cached script evaluators. public void Dispose() diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ScriptedAlarms/DependencyMuxTagUpstreamSource.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ScriptedAlarms/DependencyMuxTagUpstreamSource.cs index 9c7c741f..5466ab49 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ScriptedAlarms/DependencyMuxTagUpstreamSource.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ScriptedAlarms/DependencyMuxTagUpstreamSource.cs @@ -42,8 +42,10 @@ public sealed class DependencyMuxTagUpstreamSource : ITagUpstreamSource // publish. private const uint StatusNeverPushed = OpcUaStatus.BadWaitingForInitialData; - // Intentionally never pruned: cold-start semantics depend on retained last values so - // ReadTag can answer synchronously for any path that has ever been pushed. + // Retained last values: ReadTag answers synchronously for any path that has been pushed. Pruned + // ONLY through RetainOnly — the host calls it with the loaded dependency-ref union after every + // (re)load, so a renamed/removed raw path (a RawTree rename is a surgical remove+add) stops + // costing a boxed value + two DateTimes for the process lifetime (R02:L3). private readonly ConcurrentDictionary _cache = new(StringComparer.Ordinal); private readonly ConcurrentDictionary>> _observers @@ -91,6 +93,28 @@ public sealed class DependencyMuxTagUpstreamSource : ITagUpstreamSource } } + /// + /// Drop every cached snapshot whose path is not in . Observers are + /// untouched. Called by the host after each successful engine (re)load with the union of the loaded + /// alarms' dependency refs — exactly the set the mux will push from now on — so paths no alarm + /// references any more stop being retained. + /// + /// The paths to keep. + /// The number of cached snapshots dropped. + public int RetainOnly(IReadOnlySet paths) + { + ArgumentNullException.ThrowIfNull(paths); + var dropped = 0; + foreach (var key in _cache.Keys) + { + if (!paths.Contains(key) && _cache.TryRemove(key, out _)) dropped++; + } + return dropped; + } + + /// Test/diagnostic: the number of paths currently retained. + public int RetainedPathCount => _cache.Count; + /// public DataValueSnapshot ReadTag(string path) { diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ScriptedAlarms/ScriptedAlarmHostActor.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ScriptedAlarms/ScriptedAlarmHostActor.cs index ffa5dc4f..210a84ca 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ScriptedAlarms/ScriptedAlarmHostActor.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ScriptedAlarms/ScriptedAlarmHostActor.cs @@ -23,10 +23,16 @@ namespace ZB.MOM.WW.OtOpcUa.Runtime.ScriptedAlarms; /// cluster alerts DistributedPubSub topic. /// /// -/// The host is the engine's lifecycle owner: the caller (the driver-role startup) builds -/// the , constructs a -/// around that same upstream, and passes both here. The host disposes the engine in -/// . +/// The host is the engine's lifecycle owner. The restart-safe shape (R02:H1) is the +/// factory : +/// every incarnation builds its own + a +/// around it, and disposes them in . +/// Akka's default restart runs PostStop then re-creates the actor from the SAME Props, so the +/// legacy instance-taking Props — a fixed engine captured in the Props — restarted around a +/// disposed engine and every later LoadAsync threw: the node's scripted alarms +/// silently died. The legacy overload is kept source-compatible but is restart-safe only in the +/// weaker sense that a restart now DETACHES rather than disposes its engine (see +/// ); production should spawn through the factory. /// /// /// @@ -99,6 +105,9 @@ public sealed class ScriptedAlarmHostActor : ReceiveActor /// Warning on every clean shutdown. private sealed record AlarmsLoadCanceled; + /// Default bound on one inbound alarm command's engine op (): 10 s. + public static readonly TimeSpan DefaultCommandTimeout = TimeSpan.FromSeconds(10); + private readonly IActorRef _publishActor; private readonly IActorRef? _mux; private readonly DependencyMuxTagUpstreamSource _upstream; @@ -107,6 +116,16 @@ public sealed class ScriptedAlarmHostActor : ReceiveActor private readonly ILoggingAdapter _log = Context.GetLogger(); private readonly CancellationTokenSource _cts = new(); private readonly EventHandler _onEngineEvent; + private readonly TimeSpan _commandTimeout; + + /// True when THIS incarnation built its engine (factory Props) and therefore disposes it on + /// every stop, restart included. False for the legacy instance-taking Props: the engine outlives the + /// incarnation, so a restart only detaches from it and a final stop disposes it. + private readonly bool _ownsEngine; + + /// Set by so the it triggers can tell a restart + /// (the next incarnation reuses a legacy engine) from a genuine stop. + private bool _restarting; /// Cached local from the latest /// snapshot (null = unknown until the first snapshot arrives, or no wired). The @@ -152,6 +171,8 @@ public sealed class ScriptedAlarmHostActor : ReceiveActor /// Optional node-local live-telemetry hub (Phase 5) each cluster-wide /// alerts transition is also emitted into; null (tests) skips the emit. /// The used to instantiate the actor. + /// Legacy, instance-taking shape — see the class remarks: a supervision restart re-creates the + /// actor around these SAME instances, so prefer the factory overload in production. public static Props Props( IActorRef publishActor, IActorRef? mux, @@ -162,6 +183,60 @@ public sealed class ScriptedAlarmHostActor : ReceiveActor ITelemetryLocalHub? telemetryHub = null) => Akka.Actor.Props.Create(() => new ScriptedAlarmHostActor(publishActor, mux, upstream, engine, localNode, driverMemberCountProvider, telemetryHub)); + /// + /// Restart-safe factory Props (R02:H1): each incarnation of the actor calls + /// in its constructor and owns what it returns — the engine must + /// be constructed around the returned upstream — so a supervision restart gets a fresh, + /// undisposed engine and the next loads cleanly. + /// + /// The OPC UA publish actor emissions are bridged to. + /// Optional dependency multiplexer the host registers interest with. + /// Builds a fresh (upstream, engine) pair; called once per incarnation. + /// The local cluster node id for the Primary alerts-emit gate; null ⇒ default-emit. + /// Test seam for the alerts-emit gate's driver-member count. + /// Optional node-local live-telemetry hub. + /// Bound on one inbound alarm command's engine op; null ⇒ . + /// The used to instantiate the actor. + public static Props Props( + IActorRef publishActor, + IActorRef? mux, + Func<(DependencyMuxTagUpstreamSource Upstream, ScriptedAlarmEngine Engine)> engineFactory, + NodeId? localNode = null, + Func? driverMemberCountProvider = null, + ITelemetryLocalHub? telemetryHub = null, + TimeSpan? commandTimeout = null) => + Akka.Actor.Props.Create(() => new ScriptedAlarmHostActor(publishActor, mux, engineFactory, localNode, driverMemberCountProvider, telemetryHub, commandTimeout)); + + /// Factory-built incarnation: owns (and on every stop disposes) the engine it builds. + /// The OPC UA publish actor emissions are bridged to. + /// Optional dependency multiplexer the host registers interest with. + /// Builds this incarnation's (upstream, engine) pair. + /// The local cluster node id for the Primary alerts-emit gate. + /// Test seam for the alerts-emit gate's driver-member count. + /// Optional node-local live-telemetry hub. + /// Bound on one inbound alarm command's engine op. + public ScriptedAlarmHostActor( + IActorRef publishActor, + IActorRef? mux, + Func<(DependencyMuxTagUpstreamSource Upstream, ScriptedAlarmEngine Engine)> engineFactory, + NodeId? localNode = null, + Func? driverMemberCountProvider = null, + ITelemetryLocalHub? telemetryHub = null, + TimeSpan? commandTimeout = null) + : this(publishActor, mux, Build(engineFactory), localNode, driverMemberCountProvider, telemetryHub, ownsEngine: true, commandTimeout) + { + } + + private static (DependencyMuxTagUpstreamSource Upstream, ScriptedAlarmEngine Engine) Build( + Func<(DependencyMuxTagUpstreamSource Upstream, ScriptedAlarmEngine Engine)> engineFactory) + { + ArgumentNullException.ThrowIfNull(engineFactory); + var pair = engineFactory(); + ArgumentNullException.ThrowIfNull(pair.Upstream, "engineFactory().Upstream"); + ArgumentNullException.ThrowIfNull(pair.Engine, "engineFactory().Engine"); + return pair; + } + /// Initializes a new instance of the class. /// The OPC UA publish actor emissions are bridged to. /// Optional dependency multiplexer the host registers dependency interest with. @@ -183,14 +258,29 @@ public sealed class ScriptedAlarmHostActor : ReceiveActor NodeId? localNode = null, Func? driverMemberCountProvider = null, ITelemetryLocalHub? telemetryHub = null) + : this(publishActor, mux, (upstream, engine), localNode, driverMemberCountProvider, telemetryHub, ownsEngine: false, commandTimeout: null) + { + } + + private ScriptedAlarmHostActor( + IActorRef publishActor, + IActorRef? mux, + (DependencyMuxTagUpstreamSource Upstream, ScriptedAlarmEngine Engine) pair, + NodeId? localNode, + Func? driverMemberCountProvider, + ITelemetryLocalHub? telemetryHub, + bool ownsEngine, + TimeSpan? commandTimeout) { ArgumentNullException.ThrowIfNull(publishActor); - ArgumentNullException.ThrowIfNull(upstream); - ArgumentNullException.ThrowIfNull(engine); + ArgumentNullException.ThrowIfNull(pair.Upstream); + ArgumentNullException.ThrowIfNull(pair.Engine); _publishActor = publishActor; _mux = mux; - _upstream = upstream; - _engine = engine; + _upstream = pair.Upstream; + _engine = pair.Engine; + _ownsEngine = ownsEngine; + _commandTimeout = commandTimeout is { } t && t > TimeSpan.Zero ? t : DefaultCommandTimeout; _localNode = localNode; _driverMemberCountProvider = driverMemberCountProvider; _telemetryHub = telemetryHub; @@ -294,8 +384,15 @@ public sealed class ScriptedAlarmHostActor : ReceiveActor // subscriptions exist, so any DependencyValueChanged the mux delivers will be observed by the // engine. RegisterInterest replaces a subscriber's prior interest set (see DependencyMuxActor), // so a re-Apply with a fresh union simply supersedes the old one — no explicit unregister needed. - _mux?.Tell(new DependencyMuxActor.RegisterInterest(msg.DepRefs, Self)); - _log.Debug("ScriptedAlarmHost: loaded; registered mux interest for {Count} dep refs", msg.DepRefs.Count); + // ReplayRetained: the mux replays the last value it saw for each ref, so a fresh engine (a + // supervision restart builds one around an EMPTY upstream) converges immediately instead of + // waiting for every input to change again. + _mux?.Tell(new DependencyMuxActor.RegisterInterest(msg.DepRefs, Self, ReplayRetained: true)); + // Prune the upstream's retained snapshots to the loaded set (R02:L3): a path no alarm references + // any more will never be pushed again, so its last value is dead weight for the process lifetime. + var dropped = _upstream.RetainOnly(new HashSet(msg.DepRefs, StringComparer.Ordinal)); + _log.Debug("ScriptedAlarmHost: loaded; registered mux interest for {Count} dep refs (pruned {Dropped} retained path(s))", + msg.DepRefs.Count, dropped); ReassertConditionNodes(); } @@ -591,18 +688,25 @@ public sealed class ScriptedAlarmHostActor : ReceiveActor return; } + // Bounded (R02:H3): every op ends in IAlarmStateStore.SaveAsync (LocalDb/SQLite), and this is a + // ReceiveAsync — the mailbox is suspended until the op returns, so an unbounded await on a hung + // file lock stalled dependency-value ingestion for the duration. Linked to the actor's lifetime + // token so a stop still cancels promptly. + using var cts = CancellationTokenSource.CreateLinkedTokenSource(_cts.Token); + cts.CancelAfter(_commandTimeout); + var ct = cts.Token; try { switch (cmd.Operation) { case "Acknowledge": - await _engine.AcknowledgeAsync(cmd.AlarmId, cmd.User, cmd.Comment, CancellationToken.None); + await _engine.AcknowledgeAsync(cmd.AlarmId, cmd.User, cmd.Comment, ct); break; case "Confirm": - await _engine.ConfirmAsync(cmd.AlarmId, cmd.User, cmd.Comment, CancellationToken.None); + await _engine.ConfirmAsync(cmd.AlarmId, cmd.User, cmd.Comment, ct); break; case "OneShotShelve": - await _engine.OneShotShelveAsync(cmd.AlarmId, cmd.User, CancellationToken.None); + await _engine.OneShotShelveAsync(cmd.AlarmId, cmd.User, ct); break; case "TimedShelve": // A timed shelve needs the absolute unshelve instant. T18 derives it from the OPC UA @@ -614,16 +718,16 @@ public sealed class ScriptedAlarmHostActor : ReceiveActor cmd.AlarmId); return; } - await _engine.TimedShelveAsync(cmd.AlarmId, cmd.User, unshelveAt, CancellationToken.None); + await _engine.TimedShelveAsync(cmd.AlarmId, cmd.User, unshelveAt, ct); break; case "Unshelve": - await _engine.UnshelveAsync(cmd.AlarmId, cmd.User, CancellationToken.None); + await _engine.UnshelveAsync(cmd.AlarmId, cmd.User, ct); break; case "Enable": - await _engine.EnableAsync(cmd.AlarmId, cmd.User, CancellationToken.None); + await _engine.EnableAsync(cmd.AlarmId, cmd.User, ct); break; case "Disable": - await _engine.DisableAsync(cmd.AlarmId, cmd.User, CancellationToken.None); + await _engine.DisableAsync(cmd.AlarmId, cmd.User, ct); break; case "AddComment": if (string.IsNullOrWhiteSpace(cmd.Comment)) @@ -631,7 +735,7 @@ public sealed class ScriptedAlarmHostActor : ReceiveActor _log.Warning("ScriptedAlarmHost: rejecting AddComment for {AlarmId} — empty comment text", cmd.AlarmId); return; } - await _engine.AddCommentAsync(cmd.AlarmId, cmd.User, cmd.Comment, CancellationToken.None); + await _engine.AddCommentAsync(cmd.AlarmId, cmd.User, cmd.Comment, ct); break; default: _log.Warning("ScriptedAlarmHost: ignoring AlarmCommand with unknown operation {Op} for {AlarmId}", @@ -639,6 +743,11 @@ public sealed class ScriptedAlarmHostActor : ReceiveActor break; } } + catch (OperationCanceledException) when (!_cts.IsCancellationRequested) + { + _log.Warning("ScriptedAlarmHost: engine op {Op} for alarm {AlarmId} timed out after {Timeout} — the condition-state store is stalled", + cmd.Operation, cmd.AlarmId, _commandTimeout); + } catch (Exception ex) { // A failing engine op must not crash the actor — mirror OnLoadFailed's log-and-stay-inert style. @@ -672,16 +781,28 @@ public sealed class ScriptedAlarmHostActor : ReceiveActor base.PreStart(); } + /// + /// Akka's default PreRestart stops the children and calls . The flag + /// lets that keep a legacy (Props-captured) engine alive for the next incarnation + /// instead of disposing the instance it is about to be re-created around. + protected override void PreRestart(Exception reason, object message) + { + _restarting = true; + base.PreRestart(reason, message); + } + /// protected override void PostStop() { // Unregister mux interest first so no further DependencyValueChanged arrives while we tear down. _mux?.Tell(new DependencyMuxActor.UnregisterInterest(Self)); // Cancel any in-flight LoadAsync, detach the OnEvent handler (so a late engine emission can't - // Tell a stopping actor), then dispose the engine (which drains its background work + clears). + // Tell a stopping actor), then dispose the engine (which drains its background work + clears) — + // unless this is a RESTART around a legacy Props-captured engine, which the next incarnation will + // re-attach to (R02:H1). _cts.Cancel(); _engine.OnEvent -= _onEngineEvent; - _engine.Dispose(); + if (_ownsEngine || !_restarting) _engine.Dispose(); _cts.Dispose(); base.PostStop(); } diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/DependencyConsumerMuxAdapter.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/DependencyConsumerMuxAdapter.cs index 7011492d..b8dc818f 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/DependencyConsumerMuxAdapter.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/DependencyConsumerMuxAdapter.cs @@ -62,7 +62,10 @@ public sealed class DependencyConsumerMuxAdapter : ReceiveActor var refs = _consumer.DependencyRefs.ToList(); // A RegisterInterest replaces the prior interest set for this subscriber (mux is idempotent on // re-register), so re-registering after an apply cleanly adopts an added/removed ref. - _mux.Tell(new DependencyMuxActor.RegisterInterest(refs, Self)); + // ReplayRetained (R07:H6): a driver Restart is a NEW consumer behind a new adapter; the mux replays + // the last value of every ref it retained so the calc tags compute from current inputs at once + // instead of sitting BadWaitingForInitialData until each input happens to change. + _mux.Tell(new DependencyMuxActor.RegisterInterest(refs, Self, ReplayRetained: true)); _log.Debug("DependencyConsumerMuxAdapter: registered {Count} dependency ref(s)", refs.Count); } diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/DependencyMuxActor.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/DependencyMuxActor.cs index fe57da4e..40e9bf19 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/DependencyMuxActor.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/DependencyMuxActor.cs @@ -26,32 +26,134 @@ namespace ZB.MOM.WW.OtOpcUa.Runtime.VirtualTags; /// receive as well, for direct senders and tests. /// The mux is deliberately not a DPS subscriber — virtual-tag evaluation is local to each node and /// would over-emit if it spanned the cluster. +/// +/// +/// Last-value retention + replay (R07:H6, bounded in review fix round 1 / I2). The mux +/// retains the last (value, status, timestamp) of a ref only while at least one subscriber +/// registered with names it (the virtual-tag +/// actors, the Calculation mux adapter, the scripted-alarm host). A registration that asks receives +/// one batch of the retained values for its refs, in the shape a driver burst arrives in. The case +/// this serves is a subscriber that goes away and comes back: a Calculation driver Restart is a new +/// driver instance + a new mux adapter, and before this every calc tag sat +/// BadWaitingForInitialData until each of its inputs happened to change again. So when a +/// ref's last replay-opting subscriber leaves, its value is kept for +/// (default ; a returning replay registration inside it cancels +/// the release), then dropped together with the ref's entry. +/// +/// +/// A subscriber that does NOT opt in retains nothing: the continuous-historization recorder +/// registers every historized ref on the node (a replay there would record a stale sample per tag +/// per deploy), and retaining on its behalf made the map grow with the historized address space and +/// never shrink. Memory is therefore bounded by the refs replay-opting subscribers currently name, +/// plus those released within the last grace window. A ref with no subscriber and nothing retained +/// has no entry at all. +/// +/// +/// Source removal. The mux records which driver instance last published each retained ref; +/// evicts every value that driver produced, so a removed driver's last +/// Good is never replayed as current. A comms-loss fan (a Bad batch) already overwrites the retained +/// value with Bad. ⚠️ As of fix round 1 no production actor sends yet — +/// DriverHostActor (outside the scripting lane) must Tell it when it stops / removes a driver +/// child. Until then a removed driver's last value can still be replayed to a replay-opting +/// subscriber that re-registers for that ref while another replay-opting subscriber holds it, or +/// within the grace window. +/// /// -public sealed class DependencyMuxActor : ReceiveActor +public sealed class DependencyMuxActor : ReceiveActor, IWithTimers { public const string ActorName = "dependency-mux"; + /// How long a ref's retained value outlives its last replay-opting subscriber. + public static readonly TimeSpan DefaultRetentionGrace = TimeSpan.FromMinutes(2); + /// Register a subscriber's interest in a set of tag refs. Idempotent on re-register — /// the second call replaces the prior interest set for that subscriber. - public sealed record RegisterInterest(IReadOnlyList TagRefs, IActorRef Subscriber); + /// The refs the subscriber wants. + /// The subscriber. + /// When true, the mux retains the last value of every ref in + /// while this subscriber is registered, and immediately sends the subscriber one + /// holding the last retained value of every ref it has + /// one for (nothing when it has none). + public sealed record RegisterInterest(IReadOnlyList TagRefs, IActorRef Subscriber, bool ReplayRetained = false); /// Unregister every interest held by . Sent on PostStop by /// the subscriber, or by Terminated handling when the mux watches. public sealed record UnregisterInterest(IActorRef Subscriber); - private readonly Dictionary> _byRef = new(StringComparer.Ordinal); - private readonly Dictionary> _bySubscriber = new(); + /// A driver instance was removed / stopped: evict every retained value it produced so it is + /// never replayed. Subscriptions are untouched. + /// The removed driver instance. + public sealed record SourceRemoved(string DriverInstanceId); + + private sealed class SweepReleased + { + public static readonly SweepReleased Instance = new(); + } + + private const string SweepTimerKey = "sweep-released"; + + /// Per-ref state. One lookup on the hot path answers both "who wants it" and "retain it?". + private sealed class RefEntry + { + public readonly HashSet Subscribers = new(); + + /// Registered subscribers of this ref that opted into replay. + public int Replayers; + + /// When the last replay-opting subscriber left (retention in grace), or null. + public DateTime? ReleasedAtUtc; + + public VirtualTagActor.DependencyValueChanged? Last; + public string? LastSource; + + public bool Retains => Replayers > 0 || ReleasedAtUtc is not null; + public bool IsDead => Subscribers.Count == 0 && Replayers == 0 && Last is null; + + public void Forget() + { + Last = null; + LastSource = null; + ReleasedAtUtc = null; + } + } + + private sealed record Registration(HashSet Refs, bool Replay); + + private readonly Dictionary _byRef = new(StringComparer.Ordinal); + private readonly Dictionary _bySubscriber = new(); private readonly ILoggingAdapter _log = Context.GetLogger(); + /// How long a released ref's value is kept. + public TimeSpan RetentionGrace { get; } + + /// + public ITimerScheduler Timers { get; set; } = null!; + + /// Test hook — refs that currently hold a retained value. + internal int RetainedRefCount => _byRef.Values.Count(e => e.Last is not null); + + /// Test hook — refs the mux holds any state for (subscribers or a retained value). + internal int TrackedRefCount => _byRef.Count; + /// Creates props for the DependencyMuxActor. + /// How long a ref's value outlives its last replay-opting subscriber; + /// null ⇒ . /// The props for creating this actor. - public static Props Props() => Akka.Actor.Props.Create(); + public static Props Props(TimeSpan? retentionGrace = null) + { + var grace = retentionGrace ?? DefaultRetentionGrace; + return Akka.Actor.Props.Create(() => new DependencyMuxActor(grace)); + } /// Initializes a new instance of the class. - public DependencyMuxActor() + /// See ; non-positive ⇒ . + public DependencyMuxActor(TimeSpan retentionGrace) { + RetentionGrace = retentionGrace > TimeSpan.Zero ? retentionGrace : DefaultRetentionGrace; Receive(OnRegister); Receive(msg => RemoveSubscriber(msg.Subscriber)); + Receive(OnSourceRemoved); + Receive(_ => OnSweep()); Receive(OnAttributeValuePublished); Receive(OnAttributeValueBatchPublished); Receive(msg => RemoveSubscriber(msg.ActorRef)); @@ -59,60 +161,125 @@ public sealed class DependencyMuxActor : ReceiveActor private void OnRegister(RegisterInterest msg) { - // Replace any prior interest set so re-registers on actor restart don't leak old refs. - if (_bySubscriber.TryGetValue(msg.Subscriber, out var priorRefs)) - { - foreach (var r in priorRefs) - { - if (_byRef.TryGetValue(r, out var set)) - { - set.Remove(msg.Subscriber); - if (set.Count == 0) _byRef.Remove(r); - } - } - } + // Replace any prior interest set so re-registers on actor restart don't leak old refs. Detaching first + // may put a ref into grace; the re-attach below takes it straight back out. + Detach(msg.Subscriber); var refs = new HashSet(msg.TagRefs, StringComparer.Ordinal); - _bySubscriber[msg.Subscriber] = refs; + _bySubscriber[msg.Subscriber] = new Registration(refs, msg.ReplayRetained); + List? replay = null; foreach (var r in refs) { - if (!_byRef.TryGetValue(r, out var set)) + if (!_byRef.TryGetValue(r, out var entry)) { - set = new HashSet(); - _byRef[r] = set; + entry = new RefEntry(); + _byRef[r] = entry; } - set.Add(msg.Subscriber); + entry.Subscribers.Add(msg.Subscriber); + if (!msg.ReplayRetained) continue; + entry.Replayers++; + entry.ReleasedAtUtc = null; + if (entry.Last is { } retained) + (replay ??= []).Add(retained); } Context.Watch(msg.Subscriber); - _log.Debug("DependencyMux: subscriber {Sub} registered for {Count} refs", msg.Subscriber, refs.Count); + _log.Debug("DependencyMux: subscriber {Sub} registered for {Count} refs (replay {Replay})", + msg.Subscriber, refs.Count, msg.ReplayRetained); + + // One batch, after the registration is complete, in exactly the shape a driver burst arrives in — + // so the subscriber's hot path handles it with no special case. + if (replay is not null) + { + msg.Subscriber.Tell(new VirtualTagActor.DependencyValueBatch(replay)); + _log.Debug("DependencyMux: replayed {Count} retained value(s) to {Sub}", replay.Count, msg.Subscriber); + } } private void RemoveSubscriber(IActorRef subscriber) { - if (!_bySubscriber.TryGetValue(subscriber, out var refs)) return; - foreach (var r in refs) - { - if (_byRef.TryGetValue(r, out var set)) - { - set.Remove(subscriber); - if (set.Count == 0) _byRef.Remove(r); - } - } - _bySubscriber.Remove(subscriber); + if (!Detach(subscriber)) return; Context.Unwatch(subscriber); _log.Debug("DependencyMux: subscriber {Sub} removed", subscriber); } + /// Drop 's registration. A ref losing its last replay-opting + /// subscriber goes into grace; a ref left with no state at all is removed. + private bool Detach(IActorRef subscriber) + { + if (!_bySubscriber.Remove(subscriber, out var registration)) return false; + var now = DateTime.UtcNow; + var released = false; + foreach (var r in registration.Refs) + { + if (!_byRef.TryGetValue(r, out var entry)) continue; + entry.Subscribers.Remove(subscriber); + if (registration.Replay && --entry.Replayers == 0 && entry.Last is not null) + { + entry.ReleasedAtUtc = now; + released = true; + } + if (entry.IsDead) _byRef.Remove(r); + } + if (released && !Timers.IsTimerActive(SweepTimerKey)) + Timers.StartPeriodicTimer(SweepTimerKey, SweepReleased.Instance, RetentionGrace); + return true; + } + + /// Drop retained values whose grace has run out — with a periodic sweep at the grace interval a + /// released value lives between one and two grace periods — and stop the sweep once nothing is in grace. + private void OnSweep() + { + var cutoff = DateTime.UtcNow - RetentionGrace; + var stillInGrace = false; + List? dead = null; + foreach (var (r, entry) in _byRef) + { + if (entry.ReleasedAtUtc is not { } releasedAt) continue; + if (releasedAt > cutoff) + { + stillInGrace = true; + continue; + } + entry.Forget(); + if (entry.IsDead) (dead ??= []).Add(r); + } + if (dead is not null) + foreach (var r in dead) _byRef.Remove(r); + if (!stillInGrace) Timers.Cancel(SweepTimerKey); + } + + private void OnSourceRemoved(SourceRemoved msg) + { + List? dead = null; + var evicted = 0; + foreach (var (r, entry) in _byRef) + { + if (entry.Last is null || !string.Equals(entry.LastSource, msg.DriverInstanceId, StringComparison.Ordinal)) + continue; + entry.Forget(); + evicted++; + if (entry.IsDead) (dead ??= []).Add(r); + } + if (dead is not null) + foreach (var r in dead) _byRef.Remove(r); + _log.Debug("DependencyMux: source {Driver} removed — evicted {Count} retained value(s)", msg.DriverInstanceId, evicted); + } + private void OnAttributeValuePublished(DriverInstanceActor.AttributeValuePublished msg) { - if (!_byRef.TryGetValue(msg.FullReference, out var subscribers) || subscribers.Count == 0) + if (!_byRef.TryGetValue(msg.FullReference, out var entry)) { - // No virtual tag cares about this ref — drop. Common in normal operation; the address + // Nothing is registered for (or retaining) this ref — drop. Common in normal operation; the address // space carries thousands of tags and only a fraction feed virtual-tag expressions. return; } var dep = new VirtualTagActor.DependencyValueChanged(msg.FullReference, msg.Value, msg.TimestampUtc, msg.StatusCode); - foreach (var sub in subscribers) + if (entry.Retains) + { + entry.Last = dep; + entry.LastSource = msg.DriverInstanceId; + } + foreach (var sub in entry.Subscribers) { // A single-item batch, so the mux emits exactly ONE message shape and every subscriber needs // only the batch receive on its hot path. One list per subscriber: batch ownership transfers @@ -122,18 +289,9 @@ public sealed class DependencyMuxActor : ReceiveActor } } - /// Filters one batched driver production burst per item and delivers each subscriber's matched - /// slice as ONE . Items nobody registered for are - /// dropped (the common case: only a fraction of an address space feeds virtual-tag expressions), so a - /// burst of N values costs one inbound message plus one outbound message per genuinely interested - /// SUBSCRIBER — not per (item, subscriber) pair as it did when this fanned out per value. That is what - /// lets evaluate its script once per burst instead of once per input. - /// The registered set is NOT just virtual-tag inputs: ContinuousHistorizationRecorder - /// registers interest in every historized ref, so on a historizing node can be - /// large and a sizeable fraction of each burst resolves. private void OnAttributeValueBatchPublished(DriverInstanceActor.AttributeValueBatchPublished msg) { - // Nobody has registered anything — skip the whole burst rather than probing an empty map per item. + // Nothing registered and nothing retained — skip the whole burst rather than probing an empty map per item. if (_byRef.Count == 0) return; // Allocated lazily on the first matched item: a burst in which nothing is registered for — still @@ -146,8 +304,15 @@ public sealed class DependencyMuxActor : ReceiveActor for (var i = 0; i < count; i++) { var item = msg.Items[i]; - if (!_byRef.TryGetValue(item.FullReference, out var subscribers) || subscribers.Count == 0) continue; + if (!_byRef.TryGetValue(item.FullReference, out var entry)) continue; var dep = new VirtualTagActor.DependencyValueChanged(item.FullReference, item.Value, item.TimestampUtc, item.StatusCode); + if (entry.Retains) + { + entry.Last = dep; + entry.LastSource = msg.DriverInstanceId; + } + var subscribers = entry.Subscribers; + if (subscribers.Count == 0) continue; // retained (in grace) for a returning subscriber; nobody to forward to now perSubscriber ??= new Dictionary>(); foreach (var sub in subscribers) { diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagActor.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagActor.cs index 3d2a3058..8c7b4f41 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagActor.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagActor.cs @@ -7,6 +7,7 @@ using ZB.MOM.WW.OtOpcUa.Commons.Observability; using ZB.MOM.WW.OtOpcUa.Commons.OpcUa; using ZB.MOM.WW.OtOpcUa.Commons.Types; using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; using ZB.MOM.WW.OtOpcUa.Runtime.Telemetry; namespace ZB.MOM.WW.OtOpcUa.Runtime.VirtualTags; @@ -76,6 +77,10 @@ public sealed class VirtualTagActor : ReceiveActor private readonly IReadOnlyList _dependencyRefs; private readonly IActorRef? _mux; private readonly ITelemetryLocalHub? _telemetryHub; + // R02:P6 — a script failing on every trigger of a 1 Hz input published one cluster-wide DPS + // ScriptLogEntry per second per tag; 200 such tags shed everyone's entries out of the bounded + // telemetry channels. The per-failure entry is now rate-limited per tag (20/min + one summary). + private readonly ScriptLogRateLimiter _failureLogLimiter; private readonly ILoggingAdapter _log = Context.GetLogger(); // Dependency SNAPSHOTS, not bare values (archreview 02/S14): the status code is what distinguishes a // comms-lost input from a genuine Good null, and it is what the script reads through @@ -104,6 +109,8 @@ public sealed class VirtualTagActor : ReceiveActor /// Optional reference to a dependency multiplexer actor. /// Optional node-local live-telemetry hub each script-log entry is also /// emitted into (Phase 5); null (tests) simply skips the emit. + /// Rate limiter for this tag's per-failure script-log entries; null ⇒ + /// the default 20 per minute + one summary. /// A configured for creating the actor. public static Props Props( string virtualTagId, @@ -113,7 +120,8 @@ public sealed class VirtualTagActor : ReceiveActor Func? publisherFactory = null, IReadOnlyList? dependencyRefs = null, IActorRef? mux = null, - ITelemetryLocalHub? telemetryHub = null) => + ITelemetryLocalHub? telemetryHub = null, + ScriptLogRateLimiter? failureLogLimiter = null) => Akka.Actor.Props.Create(() => new VirtualTagActor( virtualTagId, expression, evaluator ?? NullVirtualTagEvaluator.Instance, @@ -121,7 +129,8 @@ public sealed class VirtualTagActor : ReceiveActor publisherFactory, dependencyRefs ?? Array.Empty(), mux, - telemetryHub)); + telemetryHub, + failureLogLimiter)); /// Initializes a virtual tag actor with the given configuration and dependencies. /// Unique identifier for the virtual tag. @@ -133,6 +142,8 @@ public sealed class VirtualTagActor : ReceiveActor /// Optional reference to a dependency multiplexer actor. /// Optional node-local live-telemetry hub each script-log entry is also /// emitted into (Phase 5); null (tests) simply skips the emit. + /// Rate limiter for this tag's per-failure script-log entries; null ⇒ + /// the default 20 per minute + one summary. public VirtualTagActor( string virtualTagId, string expression, @@ -141,7 +152,8 @@ public sealed class VirtualTagActor : ReceiveActor Func? publisherFactory, IReadOnlyList dependencyRefs, IActorRef? mux, - ITelemetryLocalHub? telemetryHub = null) + ITelemetryLocalHub? telemetryHub = null, + ScriptLogRateLimiter? failureLogLimiter = null) { _virtualTagId = virtualTagId; _scriptId = scriptId; @@ -151,6 +163,7 @@ public sealed class VirtualTagActor : ReceiveActor _dependencyRefs = dependencyRefs; _mux = mux; _telemetryHub = telemetryHub; + _failureLogLimiter = failureLogLimiter ?? new ScriptLogRateLimiter(); Receive(OnDependencyChanged); Receive(OnDependencyBatch); @@ -162,7 +175,9 @@ public sealed class VirtualTagActor : ReceiveActor { if (_mux is not null && _dependencyRefs.Count > 0) { - _mux.Tell(new DependencyMuxActor.RegisterInterest(_dependencyRefs, Self)); + // ReplayRetained: a respawned child (plan edit, supervision restart) evaluates from the mux's + // last-known inputs at once instead of waiting for each to change again. + _mux.Tell(new DependencyMuxActor.RegisterInterest(_dependencyRefs, Self, ReplayRetained: true)); } } @@ -353,7 +368,18 @@ public sealed class VirtualTagActor : ReceiveActor private void OnEvaluationFailed(string reason, string level, DateTime timestampUtc) { OtOpcUaTelemetry.VirtualTagEval.Add(1, new KeyValuePair("outcome", "fail")); - PublishLog(level, reason); + + // Rate-limited per tag (R02:P6): the first 20 failures a minute publish as before; the rest are + // counted and surfaced as ONE summary entry when the window rolls. The metric above and the Bad + // publish below are not limited — only the cluster-wide log fan-out is. + var admission = _failureLogLimiter.Admit(_virtualTagId); + if (admission.SuppressedInPreviousWindow > 0) + { + PublishLog("Warning", + $"{admission.SuppressedInPreviousWindow} further evaluation failure(s) were suppressed from the script log " + + $"in the previous {_failureLogLimiter.Window.TotalSeconds:F0} s (limit {_failureLogLimiter.LimitPerWindow}/window); last: {reason}"); + } + if (admission.Admitted) PublishLog(level, reason); if ((_hasPublished && _lastPublishedStatus == OpcUaStatus.BadInternalError) || !AllDependenciesArrived()) { diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagHostActor.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagHostActor.cs index d00dfb36..f97fa387 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagHostActor.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagHostActor.cs @@ -3,6 +3,7 @@ using Akka.Event; using ZB.MOM.WW.OtOpcUa.Commons.Engines; using ZB.MOM.WW.OtOpcUa.Commons.OpcUa; using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; using ZB.MOM.WW.OtOpcUa.Core.VirtualTags; using ZB.MOM.WW.OtOpcUa.OpcUaServer; using ZB.MOM.WW.OtOpcUa.Runtime.OpcUa; @@ -112,6 +113,11 @@ public sealed class VirtualTagHostActor : ReceiveActor (_evaluator as IScriptCacheOwner)?.ClearCompiledScripts(); } + // Every apply is a deploy, and a deploy lifts the run guard's quarantines unconditionally — "the + // operator redeployed to retry" is one of the two documented ways out of a quarantine (the other, + // an edited expression, the guard detects on its own). Cheap on a no-op redeploy (an empty map). + (_evaluator as IScriptQuarantineOwner)?.ResetQuarantines(); + var desired = new HashSet(msg.Plans.Select(p => p.VirtualTagId), StringComparer.Ordinal); // Stop + forget children whose vtagId is no longer desired. Stopping the child triggers its diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Configuration.Tests/DraftValidatorCalculationTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Configuration.Tests/DraftValidatorCalculationTests.cs index 0b20f490..b68fb1cd 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Configuration.Tests/DraftValidatorCalculationTests.cs +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Configuration.Tests/DraftValidatorCalculationTests.cs @@ -55,7 +55,10 @@ public sealed class DraftValidatorCalculationTests Tags = [CalcTagRow("t-1", "dev-1", "a", "{\"changeTriggered\":true}")], }; - DraftValidator.Validate(draft).ShouldContain(e => e.Code == "CalculationScriptMissing" && e.Context == "t-1"); + var errors = DraftValidator.Validate(draft); + errors.ShouldContain(e => e.Code == "CalculationScriptMissing" && e.Context == "t-1"); + errors.ShouldNotContain(e => e.Code == "CalculationNoEffectiveTrigger", + "an unresolved script has no reads to count — the missing script is the one error to report"); } [Fact] @@ -70,7 +73,10 @@ public sealed class DraftValidatorCalculationTests Scripts = [], }; - DraftValidator.Validate(draft).ShouldContain(e => e.Code == "CalculationScriptNotFound" && e.Context == "t-1"); + var errors = DraftValidator.Validate(draft); + errors.ShouldContain(e => e.Code == "CalculationScriptNotFound" && e.Context == "t-1"); + errors.ShouldNotContain(e => e.Code == "CalculationNoEffectiveTrigger", + "an unresolved script has no reads to count — the missing script is the one error to report"); } [Fact] @@ -82,7 +88,9 @@ public sealed class DraftValidatorCalculationTests DriverInstances = [CalcDriver()], Devices = [Device("dev-1", "di-calc", "engine")], Tags = [CalcTagRow("t-1", "dev-1", "a", Cfg("s1"))], - Scripts = [ScriptRow("s1", "return 42.0;")], + // A read, so the change trigger is effective (a constant change-triggered script with no timer + // is now itself a deploy error — CalculationNoEffectiveTrigger). + Scripts = [ScriptRow("s1", "return (double)ctx.GetTag(\"mb/plc/reg\").Value + 42.0;")], }; DraftValidator.Validate(draft).ShouldNotContain(e => e.Code.StartsWith("Calculation")); @@ -132,6 +140,58 @@ public sealed class DraftValidatorCalculationTests msg.ShouldContain("calc/engine/b"); } + // ── effective-trigger gate (R07:U5) ───────────────────────────────────────────────────── + + [Fact] + public void Change_triggered_tag_with_no_literal_read_and_no_timer_is_rejected() + { + var draft = new DraftSnapshot + { + GenerationId = 1, ClusterId = "c", + DriverInstances = [CalcDriver()], + Devices = [Device("dev-1", "di-calc", "engine")], + Tags = [CalcTagRow("t-1", "dev-1", "a", Cfg("s1"))], + Scripts = [ScriptRow("s1", "return ctx.Now.Hour;")], + }; + + DraftValidator.Validate(draft).ShouldContain(e => + e.Code == "CalculationNoEffectiveTrigger" && e.Context == "t-1" && e.Message.Contains("no literal ctx.GetTag")); + } + + [Fact] + public void Tag_with_change_trigger_off_and_no_timer_is_rejected() + { + var draft = new DraftSnapshot + { + GenerationId = 1, ClusterId = "c", + DriverInstances = [CalcDriver()], + Devices = [Device("dev-1", "di-calc", "engine")], + Tags = [CalcTagRow("t-1", "dev-1", "a", "{\"scriptId\":\"s1\",\"changeTriggered\":false}")], + Scripts = [ScriptRow("s1", "return (double)ctx.GetTag(\"mb/plc/reg\").Value;")], + }; + + DraftValidator.Validate(draft).ShouldContain(e => e.Code == "CalculationNoEffectiveTrigger" && e.Context == "t-1"); + } + + [Theory] + [InlineData("{\"scriptId\":\"s1\",\"changeTriggered\":true,\"timerIntervalMs\":1000}", "return ctx.Now.Hour;")] // timer rescues a read-less script + [InlineData("{\"scriptId\":\"s1\",\"changeTriggered\":false,\"timerIntervalMs\":500}", "return 1.0;")] // timer-only tag + [InlineData("{\"scriptId\":\"s1\",\"changeTriggered\":true}", "return (double)ctx.GetTag(\"mb/plc/reg\").Value;")] // change trigger with a read + [InlineData("{\"scriptId\":\"s1\"}", "return (double)ctx.GetTag(\"mb/plc/reg\").Value;")] // changeTriggered defaults to true + public void A_tag_with_an_effective_trigger_is_accepted(string cfg, string source) + { + var draft = new DraftSnapshot + { + GenerationId = 1, ClusterId = "c", + DriverInstances = [CalcDriver()], + Devices = [Device("dev-1", "di-calc", "engine")], + Tags = [CalcTagRow("t-1", "dev-1", "a", cfg)], + Scripts = [ScriptRow("s1", source)], + }; + + DraftValidator.Validate(draft).ShouldNotContain(e => e.Code == "CalculationNoEffectiveTrigger"); + } + [Fact] public void Cross_driver_ref_is_terminal_not_an_edge() { diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.AlarmHistorian.Tests/LocalDbStoreAndForwardSinkTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.AlarmHistorian.Tests/LocalDbStoreAndForwardSinkTests.cs index 9c4c6b11..97d68679 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.AlarmHistorian.Tests/LocalDbStoreAndForwardSinkTests.cs +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.AlarmHistorian.Tests/LocalDbStoreAndForwardSinkTests.cs @@ -342,6 +342,40 @@ public sealed class LocalDbStoreAndForwardSinkTests : IDisposable sink.GetStatus().DeadLetterDepth.ShouldBe(0, "purged past retention"); } + /// + /// Review R05:7 — GetStatus no longer runs a COUNT(*) table scan per call for the + /// dead-letter depth: it reads a cached counter kept in step by every dead-letter / revive / purge + /// path (the other tests in this class pin those), and resynced from storage on the same cadence as + /// the queued-row counter. A row flipped underneath the sink (the peer replicating a dead-letter in) + /// is therefore invisible until the next resync — that is the documented trade, and the resync is + /// what makes it bounded rather than permanent. + /// + [Fact] + public async Task DeadLetterDepth_is_served_from_a_cached_counter_that_the_periodic_resync_corrects() + { + var writer = new FakeWriter(); + using var sink = new LocalDbStoreAndForwardSink(Db, writer, _log); + await sink.EnqueueAsync(Event("A1"), CancellationToken.None); + await sink.EnqueueAsync(Event("A2"), CancellationToken.None); + sink.GetStatus().DeadLetterDepth.ShouldBe(0); + var probesBefore = sink.DebugCapacityProbeCount; + + // Drift the table underneath the sink, exactly as a replicated dead-letter from the pair peer would. + await Db.ExecuteAsync( + "UPDATE alarm_sf_events SET dead_lettered = 1 WHERE id IN (SELECT id FROM alarm_sf_events LIMIT 1)", + null, CancellationToken.None); + + // Cached: GetStatus did not go to the table, so it still reports the pre-drift depth… + sink.GetStatus().DeadLetterDepth.ShouldBe(0, "GetStatus serves the cached counter, not a live COUNT(*)"); + sink.DebugCapacityProbeCount.ShouldBe(probesBefore, "GetStatus must not probe storage"); + + // …and the resync (the one the enqueue cadence drives) brings both counters back in line. + await sink.DebugResyncCountersAsync(CancellationToken.None); + var status = sink.GetStatus(); + status.DeadLetterDepth.ShouldBe(1); + status.QueueDepth.ShouldBe(1); + } + /// Verifies that RetryDeadLettered requeues dead-lettered rows for retry. [Fact] public async Task RetryDeadLettered_requeues_for_retry() diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineLifecycleTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineLifecycleTests.cs new file mode 100644 index 00000000..2e9b7df6 --- /dev/null +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineLifecycleTests.cs @@ -0,0 +1,162 @@ +using Serilog; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; + +namespace ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests; + +/// +/// Review R05:1 / R05:12 / R05:3 — the engine's value cache is pruned on every reload (it used to keep +/// every path ever referenced, forever), is no longer written after Dispose, and Dispose's in-flight +/// drain is bounded (a hung store no longer hangs host shutdown). +/// +[Trait("Category", "Unit")] +public sealed class ScriptedAlarmEngineLifecycleTests +{ + private static ScriptedAlarmDefinition Alarm(string id, string predicate) => + new(AlarmId: id, EquipmentPath: "Plant/Line1/Reactor", AlarmName: id, Kind: AlarmKind.AlarmCondition, + Severity: AlarmSeverity.High, MessageTemplate: "condition", PredicateScriptSource: predicate); + + private static ScriptedAlarmEngine Build(FakeUpstream up, IAlarmStateStore? store = null) + { + var logger = new LoggerConfiguration().CreateLogger(); + return new ScriptedAlarmEngine(up, store ?? new InMemoryAlarmStateStore(), new ScriptLoggerFactory(logger), logger); + } + + [Fact] + public async Task Reload_prunes_value_cache_entries_for_paths_the_new_alarm_set_no_longer_references() + { + var up = new FakeUpstream(); + up.Set("Temp", 50); + up.Set("Pressure", 5); + using var eng = Build(up); + var ct = TestContext.Current.CancellationToken; + + await eng.LoadAsync( + [Alarm("a", """return (int)ctx.GetTag("Temp").Value > 100 || (int)ctx.GetTag("Pressure").Value > 10;""")], ct); + eng.ValueCacheCountForTest.ShouldBe(2); + + // The redeploy drops Pressure from every predicate: its entry must go with it. + await eng.LoadAsync([Alarm("a", """return (int)ctx.GetTag("Temp").Value > 100;""")], ct); + eng.ValueCacheCountForTest.ShouldBe(1); + eng.ValueCacheContainsForTest("Pressure").ShouldBeFalse(); + eng.ValueCacheContainsForTest("Temp").ShouldBeTrue(); + } + + [Fact] + public async Task A_push_after_Dispose_does_not_write_the_value_cache() + { + var up = new FakeUpstream(); + up.Set("Temp", 50); + var eng = Build(up); + await eng.LoadAsync([Alarm("a", """return (int)ctx.GetTag("Temp").Value > 100;""")], + TestContext.Current.CancellationToken); + eng.Dispose(); + eng.ValueCacheCountForTest.ShouldBe(1); + + eng.OnUpstreamChange("Late", new DataValueSnapshot(1, 0u, DateTime.UtcNow, DateTime.UtcNow)); + + eng.ValueCacheContainsForTest("Late").ShouldBeFalse("a disposed engine must not grow its cache"); + } + + [Fact] + public async Task Dispose_gives_up_on_a_store_that_never_returns_after_the_drain_bound_and_cancels_it() + { + var up = new FakeUpstream(); + up.Set("Temp", 50); + var store = new NeverReturningSaveStore(); + var eng = Build(up, store); + eng.DisposeDrainTimeout = TimeSpan.FromMilliseconds(300); + await eng.LoadAsync([Alarm("A", """return (int)ctx.GetTag("Temp").Value > 100;""")], + TestContext.Current.CancellationToken); + + store.BlockNext = true; + up.Push("Temp", 150); // Activated → SaveAsync → blocks forever (until cancelled) + await WaitForAsync(() => store.SaveInProgress); + + var sw = System.Diagnostics.Stopwatch.StartNew(); + eng.Dispose(); + sw.Stop(); + + sw.Elapsed.ShouldBeLessThan(TimeSpan.FromSeconds(5), "the drain is bounded; a hung store cannot hang shutdown"); + await WaitForAsync(() => store.ObservedCancellation, timeoutMs: 2000); + store.ObservedCancellation.ShouldBeTrue("the in-flight save was cancelled through the engine's shutdown token"); + eng.ShutdownCtsDisposedForTest.ShouldBeTrue("the cancelled save completed inside the grace, so the CTS is released"); + } + + [Fact] + public async Task Dispose_still_waits_for_a_save_that_completes_inside_the_bound() + { + // Positive control for the bound: a save that finishes promptly is drained, not cut off. + var up = new FakeUpstream(); + up.Set("Temp", 50); + var store = new NeverReturningSaveStore { ReleaseAfter = TimeSpan.FromMilliseconds(100) }; + var eng = Build(up, store); + eng.DisposeDrainTimeout = TimeSpan.FromSeconds(5); + await eng.LoadAsync([Alarm("A", """return (int)ctx.GetTag("Temp").Value > 100;""")], + TestContext.Current.CancellationToken); + + store.BlockNext = true; + up.Push("Temp", 150); + await WaitForAsync(() => store.SaveInProgress); + + eng.Dispose(); + + store.SaveInProgress.ShouldBeFalse(); + store.ObservedCancellation.ShouldBeFalse("a save that completes within the bound is never cancelled"); + store.Saved.ShouldContain("A"); + eng.ShutdownCtsDisposedForTest.ShouldBeTrue("every background task completed, so the shutdown CTS is disposed"); + Should.NotThrow(() => eng.OnUpstreamChange("Temp", new DataValueSnapshot(1, 0u, DateTime.UtcNow, DateTime.UtcNow))); + } + + private static async Task WaitForAsync(Func cond, int timeoutMs = 5000) + { + var deadline = DateTime.UtcNow.AddMilliseconds(timeoutMs); + while (DateTime.UtcNow < deadline) + { + if (cond()) return; + await Task.Delay(20); + } + throw new TimeoutException("Condition did not become true in time"); + } + + /// A store whose next SaveAsync blocks until cancelled (or until ). + private sealed class NeverReturningSaveStore : IAlarmStateStore + { + private readonly InMemoryAlarmStateStore _inner = new(); + public volatile bool BlockNext; + public volatile bool SaveInProgress; + public volatile bool ObservedCancellation; + public TimeSpan? ReleaseAfter { get; set; } + public List Saved { get; } = []; + + public Task LoadAsync(string alarmId, CancellationToken ct) => _inner.LoadAsync(alarmId, ct); + public Task> LoadAllAsync(CancellationToken ct) => _inner.LoadAllAsync(ct); + public Task RemoveAsync(string alarmId, CancellationToken ct) => _inner.RemoveAsync(alarmId, ct); + + public async Task SaveAsync(AlarmConditionState state, CancellationToken ct) + { + if (BlockNext) + { + BlockNext = false; + SaveInProgress = true; + try + { + await Task.Delay(ReleaseAfter ?? Timeout.InfiniteTimeSpan, ct).ConfigureAwait(false); + } + catch (OperationCanceledException) + { + ObservedCancellation = true; + throw; + } + finally + { + SaveInProgress = false; + } + } + lock (Saved) Saved.Add(state.AlarmId); + await _inner.SaveAsync(state, ct).ConfigureAwait(false); + } + } +} diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineRunGuardTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineRunGuardTests.cs new file mode 100644 index 00000000..ab2fde04 --- /dev/null +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineRunGuardTests.cs @@ -0,0 +1,150 @@ +using Serilog; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; + +namespace ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests; + +/// +/// runs every predicate through a keyed by +/// alarm id. A runaway predicate used to leak one pool thread per upstream push (each re-evaluation +/// spawned another abandoned run); now the orphan is one, later pushes are refused (and a +/// predicate that times out repeatedly is quarantined) — frozen at its prior state and annotated Bad quality so the operator can see it — while a +/// sibling alarm on the same engine keeps evaluating. A reload lifts the quarantine. +/// +[Trait("Category", "Unit")] +public sealed class ScriptedAlarmEngineRunGuardTests +{ + private const uint StatusBadInternalError = 0x80020000u; + + private const string SpinPredicate = + "var end = System.DateTime.UtcNow.AddSeconds(6); while (System.DateTime.UtcNow < end) { } return false;"; + + private static ScriptedAlarmDefinition Alarm(string id, string predicate) => + new(AlarmId: id, EquipmentPath: "Plant/Line1/Reactor", AlarmName: id, Kind: AlarmKind.AlarmCondition, + Severity: AlarmSeverity.High, MessageTemplate: "condition", PredicateScriptSource: predicate); + + private static ScriptedAlarmEngine Build(FakeUpstream up, ScriptingOptions? scripting = null) + { + var logger = new LoggerConfiguration().CreateLogger(); + // 500 ms, not the 60 ms the guard's own tests use: the HEALTHY alarm's first run is JIT-cold and + // must finish inside the budget on a loaded CI box, or the positive control itself times out. The + // spin predicate outlives this by 12x, so the runaway alarm still cannot finish first. + return new ScriptedAlarmEngine(up, new InMemoryAlarmStateStore(), new ScriptLoggerFactory(logger), logger, + scriptTimeout: TimeSpan.FromMilliseconds(500), scripting: scripting); + } + + [Fact] + public async Task Runaway_predicate_leaks_one_orphan_is_refused_annotated_Bad_once_and_a_sibling_keeps_evaluating() + { + var up = new FakeUpstream(); + up.Set("Temp", 50); + using var eng = Build(up); + var events = new List(); + eng.OnEvent += (_, e) => { lock (events) events.Add(e); }; + + // The load itself evaluates once (startup recovery) — that is the first, abandoned run. + await eng.LoadAsync( + [Alarm("runaway", $"var t = ctx.GetTag(\"Temp\"); {SpinPredicate}"), + Alarm("healthy", """return (int)ctx.GetTag("Temp").Value > 100;""")], + TestContext.Current.CancellationToken); + + // N more pushes while the orphan runs: every one is refused (a refusal is not a strike — I1), and + // the Bad annotation is emitted ONCE for the whole streak, not once per push (I3). + const int pushes = 4; + for (var i = 0; i < pushes; i++) + { + up.Push("Temp", 60 + i); + var expected = i + 1; + await WaitForAsync(() => eng.RunGuard.RefusedWhileRunningCount >= expected); + } + await WaitForAsync(() => eng.RunGuard.StartedRunCount >= 1 + 1 + pushes); + + eng.RunGuard.IsQuarantined("runaway", out _).ShouldBeFalse("refusals are not strikes"); + eng.RunGuard.StartedRunCount.ShouldBe(1 + 1 + pushes, "one dispatch for the runaway alarm, one per evaluation for the healthy one"); + eng.RunGuard.InFlightCount.ShouldBe(1); + + // The frozen condition is annotated Bad out of band — the operator sees WHY it is not moving — + // exactly once across the whole run of non-completions. + ScriptedAlarmEvent[] snapshot; + lock (events) snapshot = events.ToArray(); + var quality = snapshot.Where(e => e.AlarmId == "runaway" && e.Emission == EmissionKind.QualityChanged).ToArray(); + quality.Length.ShouldBe(1); + quality[0].WorstInputStatusCode.ShouldBe(StatusBadInternalError); + eng.GetState("runaway")!.Active.ShouldBe(AlarmActiveState.Inactive, "state is held, never invented"); + + // Positive control: the healthy sibling still transitions on the same engine. + up.Push("Temp", 150); + await WaitForAsync(() => eng.GetState("healthy")!.Active == AlarmActiveState.Active); + } + + /// I3 — a QUARANTINED predicate is re-attempted on every push and refused before dispatch; the + /// Bad annotation must still be emitted once, not once per push. + [Fact] + public async Task A_quarantined_predicate_emits_QualityChanged_once_across_many_pushes() + { + var up = new FakeUpstream(); + up.Set("Temp", 50); + using var eng = Build(up, new ScriptingOptions { QuarantineAfterConsecutiveTimeouts = 1 }); + var events = new List(); + eng.OnEvent += (_, e) => { lock (events) events.Add(e); }; + + await eng.LoadAsync( + [Alarm("q", $"var t = ctx.GetTag(\"Temp\"); {SpinPredicate}"), + Alarm("healthy", """return (int)ctx.GetTag("Temp").Value > 1000;""")], + TestContext.Current.CancellationToken); + eng.RunGuard.IsQuarantined("q", out _).ShouldBeTrue(); + + // Each push re-evaluates BOTH alarms (same input). The healthy sibling's dispatch count is the + // positive control proving every push was actually processed — so the quarantined alarm was + // re-attempted N times, not coalesced into one. + const int pushes = 5; + for (var i = 0; i < pushes; i++) + { + var before = eng.RunGuard.StartedRunCount; + up.Push("Temp", 60 + i); + await WaitForAsync(() => eng.RunGuard.StartedRunCount > before); + } + eng.RunGuard.StartedRunCount.ShouldBe(1 + 1 + pushes, "one runaway dispatch, then healthy-only dispatches"); + await Task.Delay(300); // absence window for trailing emissions + + ScriptedAlarmEvent[] snapshot; + lock (events) snapshot = events.ToArray(); + var quality = snapshot.Where(e => e.AlarmId == "q" && e.Emission == EmissionKind.QualityChanged).ToArray(); + quality.Length.ShouldBe(1, "one Bad annotation for the quarantine, not one per push"); + quality[0].WorstInputStatusCode.ShouldBe(StatusBadInternalError); + snapshot.ShouldNotContain(e => e.AlarmId == "healthy" && e.Emission == EmissionKind.QualityChanged); + } + + [Fact] + public async Task A_reload_lifts_the_quarantine() + { + var up = new FakeUpstream(); + up.Set("Temp", 50); + using var eng = Build(up, new ScriptingOptions { QuarantineAfterConsecutiveTimeouts = 1 }); + + await eng.LoadAsync([Alarm("a", $"var t = ctx.GetTag(\"Temp\"); {SpinPredicate}")], + TestContext.Current.CancellationToken); + eng.RunGuard.IsQuarantined("a", out _).ShouldBeTrue(); + + // The operator fixed the predicate and redeployed. + await eng.LoadAsync([Alarm("a", """return (int)ctx.GetTag("Temp").Value > 100;""")], + TestContext.Current.CancellationToken); + eng.RunGuard.IsQuarantined("a", out _).ShouldBeFalse(); + + up.Push("Temp", 150); + await WaitForAsync(() => eng.GetState("a")!.Active == AlarmActiveState.Active); + } + + private static async Task WaitForAsync(Func cond, int timeoutMs = 10_000) + { + var deadline = DateTime.UtcNow.AddMilliseconds(timeoutMs); + while (DateTime.UtcNow < deadline) + { + if (cond()) return; + await Task.Delay(25); + } + throw new TimeoutException("Condition did not become true in time"); + } +} diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmSourceLoggingTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmSourceLoggingTests.cs new file mode 100644 index 00000000..94c0408c --- /dev/null +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmSourceLoggingTests.cs @@ -0,0 +1,59 @@ +using Serilog; +using Serilog.Core; +using Serilog.Events; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; + +namespace ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests; + +/// Review R05:6 — a throwing subscriber used to be +/// swallowed with no diagnostic: a lost alarm event with no trace. It is now logged at Warning. +[Trait("Category", "Unit")] +public sealed class ScriptedAlarmSourceLoggingTests +{ + private sealed class CapturingSink : ILogEventSink + { + public List Events { get; } = []; + public void Emit(LogEvent logEvent) { lock (Events) Events.Add(logEvent); } + } + + [Fact] + public async Task A_throwing_subscriber_is_logged_at_Warning_and_does_not_crash_the_adapter() + { + var sinkCapture = new CapturingSink(); + var logger = new LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(sinkCapture).CreateLogger(); + var up = new FakeUpstream(); + up.Set("Temp", 50); + var engine = new ScriptedAlarmEngine(up, new InMemoryAlarmStateStore(), new ScriptLoggerFactory(logger), logger); + await engine.LoadAsync( + [new ScriptedAlarmDefinition("Plant/Line1::HighTemp", "Plant/Line1", "HighTemp", AlarmKind.LimitAlarm, + AlarmSeverity.High, "Temp {Temp}C", """return (int)ctx.GetTag("Temp").Value > 100;""")], + TestContext.Current.CancellationToken); + using var _e = engine; + using var source = new ScriptedAlarmSource(engine, logger); + await source.SubscribeAlarmsAsync(Array.Empty(), TestContext.Current.CancellationToken); + source.OnAlarmEvent += (_, _) => throw new InvalidOperationException("subscriber broke"); + + up.Push("Temp", 150); + + var deadline = DateTime.UtcNow.AddSeconds(10); + while (DateTime.UtcNow < deadline) + { + lock (sinkCapture.Events) + { + if (sinkCapture.Events.Any(e => e.Level == LogEventLevel.Warning && e.Exception?.Message == "subscriber broke")) + break; + } + await Task.Delay(25); + } + + LogEvent warning; + lock (sinkCapture.Events) + warning = sinkCapture.Events.Single(e => e.Level == LogEventLevel.Warning && e.Exception?.Message == "subscriber broke"); + warning.RenderMessage().ShouldContain("Plant/Line1::HighTemp"); + // The adapter survived: the engine's state still moved. + engine.GetState("Plant/Line1::HighTemp")!.Active.ShouldBe(AlarmActiveState.Active); + } +} diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLogRateLimiterTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLogRateLimiterTests.cs new file mode 100644 index 00000000..70674942 --- /dev/null +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLogRateLimiterTests.cs @@ -0,0 +1,141 @@ +using Serilog; +using Serilog.Core; +using Serilog.Events; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging; + +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests; + +/// +/// Per-source rate limit on the script-log fan-out (review R05:9 / R02:P6): a script that logs — or +/// fails — on every evaluation of a 1 Hz input used to put one entry per second per script onto the +/// cluster bus and the main log. The limiter admits the first 20 entries per source per minute, drops +/// the rest, and surfaces one summary line (with the dropped count) when the next entry arrives after +/// the window rolled — so nothing is silently lost, and a chatty script cannot shed everyone else's +/// entries out of the bounded telemetry channels. +/// +[Trait("Category", "Unit")] +public sealed class ScriptLogRateLimiterTests +{ + private sealed class Clock + { + public DateTime Now = new(2026, 1, 1, 12, 0, 0, DateTimeKind.Utc); + public void Advance(TimeSpan by) => Now += by; + } + + [Fact] + public void Admits_the_first_N_per_window_then_suppresses_and_summarises_once_the_window_rolls() + { + var clock = new Clock(); + var limiter = new ScriptLogRateLimiter(limitPerWindow: 3, window: TimeSpan.FromMinutes(1), clock: () => clock.Now); + + limiter.Admit("s1").Admitted.ShouldBeTrue(); + limiter.Admit("s1").Admitted.ShouldBeTrue(); + limiter.Admit("s1").Admitted.ShouldBeTrue(); + limiter.Admit("s1").Admitted.ShouldBeFalse(); + limiter.Admit("s1").Admitted.ShouldBeFalse(); + limiter.Admit("s1").SuppressedInPreviousWindow.ShouldBe(0, "no summary until the window rolls"); + + clock.Advance(TimeSpan.FromMinutes(1)); + var first = limiter.Admit("s1"); + first.Admitted.ShouldBeTrue("a fresh window admits again"); + first.SuppressedInPreviousWindow.ShouldBe(3, "the caller emits one summary for the three dropped entries"); + limiter.Admit("s1").SuppressedInPreviousWindow.ShouldBe(0, "the summary is reported exactly once"); + } + + [Fact] + public void Sources_are_independent() + { + var limiter = new ScriptLogRateLimiter(limitPerWindow: 1); + limiter.Admit("a").Admitted.ShouldBeTrue(); + limiter.Admit("a").Admitted.ShouldBeFalse(); + limiter.Admit("b").Admitted.ShouldBeTrue("a chatty source must not shed another source's entries"); + } + + [Fact] + public void Defaults_are_20_per_minute() + { + ScriptLogRateLimiter.DefaultLimitPerWindow.ShouldBe(20); + ScriptLogRateLimiter.DefaultWindow.ShouldBe(TimeSpan.FromMinutes(1)); + var limiter = new ScriptLogRateLimiter(); + limiter.LimitPerWindow.ShouldBe(20); + new ScriptLogRateLimiter(limitPerWindow: 3).LimitPerWindow.ShouldBe(3); + new ScriptLogRateLimiter(limitPerWindow: 0).LimitPerWindow.ShouldBe(1, "values below 1 are treated as 1"); + for (var i = 0; i < 20; i++) limiter.Admit("s").Admitted.ShouldBeTrue(); + limiter.Admit("s").Admitted.ShouldBeFalse(); + } + + // ── the two sinks ──────────────────────────────────────────────────────────────────────── + + private sealed class FakePublisher : IScriptLogPublisher + { + public List Published { get; } = []; + public void Publish(ScriptLogEntry entry) => Published.Add(entry); + } + + private static LogEvent Evt(LogEventLevel level, string template, params (string Key, string Val)[] props) + { + var tmpl = new Serilog.Parsing.MessageTemplateParser().Parse(template); + var logProps = props.Select(p => new LogEventProperty(p.Key, new ScalarValue(p.Val))); + return new LogEvent(DateTimeOffset.UtcNow, level, exception: null, tmpl, logProps); + } + + [Fact] + public void Topic_sink_rate_limits_per_source_and_publishes_a_summary_entry() + { + var clock = new Clock(); + var publisher = new FakePublisher(); + var sink = new ScriptLogTopicSink(publisher, LogEventLevel.Information, + new ScriptLogRateLimiter(limitPerWindow: 2, clock: () => clock.Now)); + + for (var i = 0; i < 5; i++) + sink.Emit(Evt(LogEventLevel.Warning, "chatty", (ScriptLoggerFactory.ScriptIdProperty, "S1"), (ScriptLoggerFactory.VirtualTagIdProperty, "V1"))); + sink.Emit(Evt(LogEventLevel.Warning, "other", (ScriptLoggerFactory.ScriptIdProperty, "S2"))); + + publisher.Published.Count(e => e.ScriptId == "S1").ShouldBe(2, "the limit is per source"); + publisher.Published.Count(e => e.ScriptId == "S2").ShouldBe(1, "another source is unaffected"); + + clock.Advance(TimeSpan.FromMinutes(1)); + sink.Emit(Evt(LogEventLevel.Warning, "chatty again", (ScriptLoggerFactory.ScriptIdProperty, "S1"), (ScriptLoggerFactory.VirtualTagIdProperty, "V1"))); + + var s1 = publisher.Published.Where(e => e.ScriptId == "S1").ToList(); + s1.Count.ShouldBe(4, "2 admitted + 1 summary + 1 admitted in the new window"); + var summary = s1[2]; + summary.Message.ShouldContain("3"); + summary.Message.ShouldContain("suppressed"); + summary.Message.ShouldContain("limit 2/window", Case.Sensitive, "the summary names the CONFIGURED limit, not the default"); + summary.VirtualTagId.ShouldBe("V1", "the summary carries the source's identity so the page attributes it"); + summary.Level.ShouldBe("Warning"); + s1[3].Message.ShouldBe("chatty again"); + } + + private sealed class CapturingSink : ILogEventSink + { + public List Events { get; } = []; + public void Emit(LogEvent logEvent) => Events.Add(logEvent); + } + + [Fact] + public void Companion_sink_rate_limits_per_script_and_mirrors_a_summary_line() + { + var clock = new Clock(); + var main = new CapturingSink(); + var mainLogger = new LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(main).CreateLogger(); + var sink = new ScriptLogCompanionSink(mainLogger, LogEventLevel.Error, + new ScriptLogRateLimiter(limitPerWindow: 2, clock: () => clock.Now)); + + for (var i = 0; i < 5; i++) + sink.Emit(Evt(LogEventLevel.Error, "boom", (ScriptLoggerFactory.ScriptNameProperty, "HighTemp"))); + main.Events.Count.ShouldBe(2); + + clock.Advance(TimeSpan.FromMinutes(1)); + sink.Emit(Evt(LogEventLevel.Error, "boom", (ScriptLoggerFactory.ScriptNameProperty, "HighTemp"))); + + main.Events.Count.ShouldBe(4); + var summary = main.Events[2].RenderMessage(); + summary.ShouldContain("HighTemp"); + summary.ShouldContain("3"); + summary.ShouldContain("suppressed"); + } +} 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 new file mode 100644 index 00000000..b4efe8af --- /dev/null +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs @@ -0,0 +1,409 @@ +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; + +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests; + +/// +/// — the per-script run quarantine shared by the virtual-tag evaluator, the +/// Calculation evaluator and the scripted-alarm engine. A timed-out script is abandoned, not stopped, so +/// before the guard every re-trigger of a runaway script leaked one more thread-pool thread; the guard +/// refuses to start a run while the previous one is still executing, quarantines a script after three +/// consecutive timeouts (a refusal is not a strike), and quarantines a script whose single run allocates past the budget. +/// +[Trait("Category", "Unit")] +public sealed class ScriptRunGuardTests +{ + /// + /// A CPU-bound script that outlives every timeout in this file but still ENDS (so the orphaned pool + /// thread it leaves behind frees itself after the test). System.DateTime is outside the sandbox + /// deny-list. + /// + private const string SpinScript = + """ + var end = System.DateTime.UtcNow.AddSeconds(6); + while (System.DateTime.UtcNow < end) { } + return 1; + """; + + private const string FastScript = "return 42;"; + + /// Outlives the 60 ms budget but finishes within ~250 ms, so the slot frees up between attempts. + private const string BriefSpinScript = + """ + var end = System.DateTime.UtcNow.AddMilliseconds(250); + while (System.DateTime.UtcNow < end) { } + return 1; + """; + + private static readonly TimeSpan ShortTimeout = TimeSpan.FromMilliseconds(60); + + private static ScriptEvaluator Compile(string source) => + ScriptEvaluator.Compile(source); + + private static Task Run(ScriptRunGuard guard, string key, string source, + ScriptEvaluator evaluator, TimeSpan? timeout = null, CancellationToken ct = default) => + guard.RunAsync(key, source, evaluator, new FakeScriptContext(), timeout ?? TimeSpan.FromSeconds(5), ct); + + [Fact] + public async Task Completed_run_returns_the_value_and_releases_the_in_flight_slot() + { + var guard = new ScriptRunGuard(); + using var fast = Compile(FastScript); + + var value = await Run(guard, "vt-1", FastScript, fast, ct: TestContext.Current.CancellationToken); + + value.ShouldBe(42); + guard.InFlightCount.ShouldBe(0); + guard.StartedRunCount.ShouldBe(1); + guard.IsQuarantined("vt-1", out _).ShouldBeFalse(); + } + + [Fact] + public async Task A_timed_out_run_throws_ScriptTimeoutException_and_keeps_the_slot_held_by_the_orphan() + { + var guard = new ScriptRunGuard(); + using var spin = Compile(SpinScript); + + await Should.ThrowAsync(() => + Run(guard, "vt-1", SpinScript, spin, ShortTimeout, TestContext.Current.CancellationToken)); + + // The abandoned script is still executing on its pool thread — the guard knows, the caller does not. + guard.InFlightCount.ShouldBe(1); + guard.StartedRunCount.ShouldBe(1); + } + + [Fact] + public async Task A_run_while_the_previous_orphan_is_still_executing_is_refused_without_starting_another() + { + var guard = new ScriptRunGuard(); + using var spin = Compile(SpinScript); + await Should.ThrowAsync(() => + Run(guard, "vt-1", SpinScript, spin, ShortTimeout, TestContext.Current.CancellationToken)); + + var ex = await Should.ThrowAsync(() => + Run(guard, "vt-1", SpinScript, spin, ShortTimeout, TestContext.Current.CancellationToken)); + + ex.Message.ShouldBe(ScriptRunGuard.PreviousRunStillRunningReason); + guard.StartedRunCount.ShouldBe(1, "the refusal must not dispatch a second Task.Run"); + guard.InFlightCount.ShouldBe(1); + guard.RefusedWhileRunningCount.ShouldBe(1); + } + + [Fact] + public async Task Three_consecutive_timeouts_quarantine_the_script_and_a_sibling_keeps_evaluating() + { + var guard = new ScriptRunGuard(); + using var spin = Compile(BriefSpinScript); + using var fast = Compile(FastScript); + var ct = TestContext.Current.CancellationToken; + + // Three timeouts in a row — each orphan is allowed to finish so the next attempt is a real run, + // not a refusal (a refusal is not a strike; see the next test). + await Should.ThrowAsync(() => Run(guard, "bad", BriefSpinScript, spin, ShortTimeout, ct)); + await WaitForIdle(guard); + await Should.ThrowAsync(() => Run(guard, "bad", BriefSpinScript, spin, ShortTimeout, ct)); + await WaitForIdle(guard); + var quarantined = await Should.ThrowAsync(() => Run(guard, "bad", BriefSpinScript, spin, ShortTimeout, ct)); + await WaitForIdle(guard); + + quarantined.Message.ShouldStartWith(ScriptRunGuard.QuarantinedReasonPrefix); + quarantined.Message.ShouldContain("3 consecutive"); + guard.IsQuarantined("bad", out var reason).ShouldBeTrue(); + reason.ShouldNotBeNull(); + guard.QuarantinedCount.ShouldBe(1); + + // A quarantined script is never dispatched again — the 4th attempt refuses before Task.Run. + await Should.ThrowAsync(() => Run(guard, "bad", BriefSpinScript, spin, ShortTimeout, ct)); + guard.StartedRunCount.ShouldBe(3); + + // Positive control: a healthy sibling on the SAME guard still runs — the quarantine is per key. + (await Run(guard, "good", FastScript, fast, ct: ct)).ShouldBe(42); + guard.IsQuarantined("good", out _).ShouldBeFalse(); + guard.StartedRunCount.ShouldBe(4); + } + + /// + /// A refusal is NOT a strike (review fix round 1, I1): on a 1 Hz trigger with a 2 s budget a single + /// 4 s overrun is one timeout followed by two refusals, and counting those would quarantine a script + /// that merely ran long once. A refusal is a Bad publish plus its counter, and it leaves the timeout + /// streak untouched — neither adding to it nor resetting it. + /// + [Fact] + public async Task Refusals_neither_count_toward_nor_reset_the_timeout_streak() + { + var guard = new ScriptRunGuard(new ScriptingOptions { QuarantineAfterConsecutiveTimeouts = 2 }); + using var spin = Compile(BriefSpinScript); + var ct = TestContext.Current.CancellationToken; + + // timeout #1, then refusals while the orphan is still running — however many, no quarantine. + await Should.ThrowAsync(() => Run(guard, "k", BriefSpinScript, spin, ShortTimeout, ct)); + for (var i = 0; i < 5; i++) + await Should.ThrowAsync(() => Run(guard, "k", BriefSpinScript, spin, ShortTimeout, ct)); + guard.IsQuarantined("k", out _).ShouldBeFalse("refusals are not strikes"); + guard.RefusedWhileRunningCount.ShouldBe(5); + await WaitForIdle(guard); + + // …and they did not RESET the streak either: the second real timeout reaches the threshold of 2. + await Should.ThrowAsync(() => Run(guard, "k", BriefSpinScript, spin, ShortTimeout, ct)); + guard.IsQuarantined("k", out _).ShouldBeTrue(); + await WaitForIdle(guard); + } + + /// + /// The thread-leak regression, and the stuck-orphan quarantine (fix round 2). Pre-guard, a + /// while(true) script on a 1 Hz trigger leaked one pool thread per trigger — 30 orphans after 30 + /// triggers, trending toward pool starvation. Now the first trigger's orphan is the only one; later + /// triggers are refused while it is young, and once it has run longer than + /// × the timeout (10 × 60 ms here — the + /// trigger cadence is scaled down from 1 Hz to keep the test short) the next refusal quarantines it. + /// A healthy sibling keeps evaluating throughout (the positive control an absence assertion needs). + /// + /// + /// The load-bearing assertions are on the guard's own bookkeeping ( + /// / ): moves with + /// every parallel test class on a loaded machine, so it is kept as a coarse secondary check only — + /// it must stay far below the 30 the leak would have produced. + /// + [Fact] + public async Task Runaway_script_leaves_one_orphan_is_quarantined_once_stuck_and_a_sibling_keeps_evaluating() + { + var guard = new ScriptRunGuard(); + using var spin = Compile(SpinScript); + using var fast = Compile(FastScript); + var ct = TestContext.Current.CancellationToken; + var threadsBefore = ThreadPool.ThreadCount; + var stuckAfter = ShortTimeout * ScriptingOptions.DefaultStuckOrphanQuarantineFactor; // 600 ms + + var healthyResults = new List(); + var outcomes = new List(); + var sw = System.Diagnostics.Stopwatch.StartNew(); + for (var trigger = 0; trigger < 30; trigger++) + { + try { await Run(guard, "runaway", SpinScript, spin, ShortTimeout, ct); outcomes.Add("value"); } + catch (ScriptTimeoutException) { outcomes.Add("timeout"); } + catch (ScriptRunRefusedException) { outcomes.Add(sw.Elapsed < stuckAfter ? "refused-young" : "refused"); } + catch (ScriptQuarantinedException) { outcomes.Add("quarantined"); } + + healthyResults.Add(await Run(guard, "healthy", FastScript, fast, ct: ct)); + await Task.Delay(50, ct); + } + + guard.InFlightCount.ShouldBe(1, "exactly one orphaned run — the first trigger's — may be executing"); + guard.StartedRunCount.ShouldBe(1 + 30, "one dispatch for the runaway script, thirty for the healthy sibling"); + outcomes[0].ShouldBe("timeout"); + outcomes.ShouldContain("refused-young", "a young orphan is only refused — a short overrun is not quarantined"); + guard.IsQuarantined("runaway", out var reason).ShouldBeTrue("the orphan outlived 10x its budget: it is stuck"); + reason!.ShouldContain("stuck"); + outcomes[^1].ShouldBe("quarantined"); + guard.QuarantinedCount.ShouldBe(1); + healthyResults.ShouldAllBe(v => v == 42); + healthyResults.Count.ShouldBe(30); + + var threadDelta = ThreadPool.ThreadCount - threadsBefore; + threadDelta.ShouldBeLessThan(15, "thirty leaked orphans would have grown the pool by ~30 threads"); + } + + /// + /// Positive control for the stuck rule: a 2x overrun (one timeout, refusals while the orphan is young) + /// is NOT quarantined, and once the orphan completes the script evaluates normally again. + /// + [Fact] + public async Task A_2x_overrun_is_not_quarantined_and_resumes_evaluating_once_the_orphan_completes() + { + var guard = new ScriptRunGuard(); + const string source = + """ + var ms = (int)(ctx.GetTag("spinMs").Value ?? 0); + var end = System.DateTime.UtcNow.AddMilliseconds(ms); + while (System.DateTime.UtcNow < end) { } + return 7; + """; + using var eval = Compile(source); + var ct = TestContext.Current.CancellationToken; + var timeout = TimeSpan.FromMilliseconds(100); + + FakeScriptContext Ctx(int spinMs) + { + var c = new FakeScriptContext(); + c.Tags["spinMs"] = new Core.Abstractions.DataValueSnapshot(spinMs, 0u, c.Now, c.Now); + return c; + } + + // Warm the JIT so the first measured run's overrun is the script's, not the compiler's. + (await guard.RunAsync("k", source, eval, Ctx(0), TimeSpan.FromSeconds(5), ct)).ShouldBe(7); + + // 2x overrun: 200 ms against a 100 ms budget — times out, then is refused while it finishes. + await Should.ThrowAsync(() => guard.RunAsync("k", source, eval, Ctx(200), timeout, ct)); + await Should.ThrowAsync(() => guard.RunAsync("k", source, eval, Ctx(0), timeout, ct)); + await WaitForIdle(guard); + + guard.IsQuarantined("k", out _).ShouldBeFalse("a 2x overrun is far below the 10x stuck threshold"); + (await guard.RunAsync("k", source, eval, Ctx(0), timeout, ct)).ShouldBe(7, "the script resumes evaluating"); + guard.QuarantinedCount.ShouldBe(0); + } + + /// The stuck rule is a knob: with ≤ 0 a + /// stuck orphan is only ever refused. + [Fact] + public async Task StuckOrphanQuarantineFactor_zero_disables_the_stuck_rule() + { + var guard = new ScriptRunGuard(new ScriptingOptions { StuckOrphanQuarantineFactor = 0 }); + using var spin = Compile(SpinScript); + var ct = TestContext.Current.CancellationToken; + + await Should.ThrowAsync(() => Run(guard, "k", SpinScript, spin, ShortTimeout, ct)); + await Task.Delay(ShortTimeout * 12, ct); + await Should.ThrowAsync(() => Run(guard, "k", SpinScript, spin, ShortTimeout, ct)); + guard.IsQuarantined("k", out _).ShouldBeFalse(); + } + + [Fact] + public async Task A_source_change_clears_the_quarantine_and_abandons_the_old_orphan_slot() + { + var guard = new ScriptRunGuard(new ScriptingOptions { QuarantineAfterConsecutiveTimeouts = 1 }); + using var spin = Compile(SpinScript); + using var fast = Compile(FastScript); + var ct = TestContext.Current.CancellationToken; + + await Should.ThrowAsync(() => Run(guard, "vt", SpinScript, spin, ShortTimeout, ct)); + guard.IsQuarantined("vt", out _).ShouldBeTrue(); + + // The operator fixed the script: a different source identity under the same key starts clean. The + // old orphan is a sunk cost — it keeps running, but it must not block the FIXED script. + (await Run(guard, "vt", FastScript, fast, ct: ct)).ShouldBe(42); + guard.IsQuarantined("vt", out _).ShouldBeFalse(); + guard.InFlightCount.ShouldBe(1, "the abandoned orphan is still counted until it finishes"); + } + + [Fact] + public async Task Reset_and_ResetAll_clear_a_quarantine() + { + var guard = new ScriptRunGuard(new ScriptingOptions { QuarantineAfterConsecutiveTimeouts = 1 }); + using var spin = Compile(SpinScript); + using var fast = Compile(FastScript); + var ct = TestContext.Current.CancellationToken; + + await Should.ThrowAsync(() => Run(guard, "a", SpinScript, spin, ShortTimeout, ct)); + await Should.ThrowAsync(() => Run(guard, "b", SpinScript, spin, ShortTimeout, ct)); + guard.QuarantinedKeys.ShouldBe(new[] { "a", "b" }, ignoreOrder: true); + + guard.Reset("a"); + guard.IsQuarantined("a", out _).ShouldBeFalse(); + guard.IsQuarantined("b", out _).ShouldBeTrue(); + + guard.ResetAll(); + guard.IsQuarantined("b", out _).ShouldBeFalse(); + // The key is usable again (a fresh slot: the orphan from the quarantined run no longer blocks it). + (await Run(guard, "b", FastScript, fast, ct: ct)).ShouldBe(42); + } + + [Fact] + public async Task A_run_that_allocates_past_the_budget_is_quarantined() + { + var guard = new ScriptRunGuard(new ScriptingOptions { MaxAllocBytesPerRun = 1024 * 1024 }); + // Writes into every array so the JIT cannot fold `new byte[N].Length` to a constant and drop the + // allocation as dead code (which is exactly what it does to the naive one-liner). + const string hungry = + "long total = 0; for (var i = 0; i < 32; i++) { var a = new byte[256 * 1024]; a[i] = 1; total += a[i] + a.Length; } return (int)total;"; + using var evaluator = Compile(hungry); + using var fast = Compile(FastScript); + var ct = TestContext.Current.CancellationToken; + + var ex = await Should.ThrowAsync(() => Run(guard, "hog", hungry, evaluator, ct: ct)); + ex.Message.ShouldContain("allocat"); + guard.IsQuarantined("hog", out var reason).ShouldBeTrue(); + reason.ShouldNotBeNull(); + reason.ShouldContain("allocat"); + + // Never dispatched again, and the slot was released (the run DID complete). + await Should.ThrowAsync(() => Run(guard, "hog", hungry, evaluator, ct: ct)); + guard.StartedRunCount.ShouldBe(1); + guard.InFlightCount.ShouldBe(0); + + // Positive control: a modest allocation under the budget is fine. + (await Run(guard, "ok", FastScript, fast, ct: ct)).ShouldBe(42); + } + + [Fact] + public async Task A_disabled_allocation_budget_never_quarantines() + { + var guard = new ScriptRunGuard(new ScriptingOptions { MaxAllocBytesPerRun = 0 }); + // Writes into every array so the JIT cannot fold `new byte[N].Length` to a constant and drop the + // allocation as dead code (which is exactly what it does to the naive one-liner). + const string hungry = + "long total = 0; for (var i = 0; i < 32; i++) { var a = new byte[256 * 1024]; a[i] = 1; total += a[i] + a.Length; } return (int)total;"; + using var evaluator = Compile(hungry); + + (await Run(guard, "hog", hungry, evaluator, ct: TestContext.Current.CancellationToken)).ShouldBe(32 * (256 * 1024 + 1)); + guard.IsQuarantined("hog", out _).ShouldBeFalse(); + } + + [Fact] + public async Task A_script_that_throws_propagates_unwrapped_and_counts_as_a_completion() + { + var guard = new ScriptRunGuard(new ScriptingOptions { QuarantineAfterConsecutiveTimeouts = 2 }); + const string throwing = "throw new System.InvalidOperationException(\"boom\");"; + using var thrower = Compile(throwing); + // A spin that outlives the timeout but finishes quickly, so the slot frees up between attempts. + const string briefSpin = + """ + var end = System.DateTime.UtcNow.AddMilliseconds(250); + while (System.DateTime.UtcNow < end) { } + return 1; + """; + using var spin = Compile(briefSpin); + var ct = TestContext.Current.CancellationToken; + + // timeout #1 + await Should.ThrowAsync(() => Run(guard, "k", briefSpin, spin, ShortTimeout, ct)); + await WaitForIdle(guard); + + // A throw is a completion — the script returned control — so the consecutive counter resets… + var ex = await Should.ThrowAsync(() => Run(guard, "k", throwing, thrower, ct: ct)); + ex.Message.ShouldBe("boom"); + guard.InFlightCount.ShouldBe(0); + + // …which is why this second timeout does NOT reach the threshold of 2. + await Should.ThrowAsync(() => Run(guard, "k", briefSpin, spin, ShortTimeout, ct)); + guard.IsQuarantined("k", out _).ShouldBeFalse(); + await WaitForIdle(guard); + } + + [Fact] + public async Task Caller_cancellation_wins_over_the_timeout() + { + var guard = new ScriptRunGuard(); + using var spin = Compile(SpinScript); + using var cts = new CancellationTokenSource(TimeSpan.FromMilliseconds(80)); + + await Should.ThrowAsync(() => + Run(guard, "k", SpinScript, spin, TimeSpan.FromSeconds(5), cts.Token)); + guard.IsQuarantined("k", out _).ShouldBeFalse(); + } + + [Fact] + public async Task Quarantine_is_observable_through_the_event_and_the_counter() + { + var guard = new ScriptRunGuard(new ScriptingOptions { QuarantineAfterConsecutiveTimeouts = 1 }); + using var spin = Compile(SpinScript); + var seen = new List<(string Key, string Reason)>(); + guard.Quarantined += (_, e) => seen.Add((e.Key, e.Reason)); + + await Should.ThrowAsync(() => + Run(guard, "k", SpinScript, spin, ShortTimeout, TestContext.Current.CancellationToken)); + + seen.ShouldHaveSingleItem(); + seen[0].Key.ShouldBe("k"); + seen[0].Reason.ShouldContain("consecutive"); + guard.QuarantinedCount.ShouldBe(1); + } + + private static async Task WaitForIdle(ScriptRunGuard guard) + { + var deadline = DateTime.UtcNow.AddSeconds(5); + while (guard.InFlightCount != 0 && DateTime.UtcNow < deadline) + await Task.Delay(10); + guard.InFlightCount.ShouldBe(0, "the brief spin must have finished"); + } +} diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptSandboxHardeningTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptSandboxHardeningTests.cs new file mode 100644 index 00000000..5c932832 --- /dev/null +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptSandboxHardeningTests.cs @@ -0,0 +1,148 @@ +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; + +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests; + +/// +/// Sandbox hardening (review R05:10): System.Threading is denied as a namespace with a +/// type-granular allow-list (CancellationToken, Interlocked, Volatile) so a +/// script can no longer park its pool thread on a blocking primitive or touch a system-global kernel +/// object; System.Type's reflection entry points (GetType(string), GetMethod*, +/// InvokeMember, …) and System.Runtime.CompilerServices.RuntimeHelpers are denied so a +/// forbidden type cannot be reached by name without ever being named syntactically. +/// +[Trait("Category", "Unit")] +public sealed class ScriptSandboxHardeningTests +{ + private static ScriptSandboxViolationException Rejects(string source) => + Should.Throw(() => + ScriptEvaluator.Compile(source)); + + // ── System.Threading blocking / synchronisation primitives ─────────────────────────────── + + [Fact] + public void Rejects_SemaphoreSlim_Wait() + { + var ex = Rejects("new System.Threading.SemaphoreSlim(0).Wait(); return 0;"); + ex.Rejections.ShouldContain(r => r.TypeName.Contains("SemaphoreSlim") && r.Namespace == "System.Threading"); + } + + [Fact] + public void Rejects_SpinWait_SpinUntil() + => Rejects("System.Threading.SpinWait.SpinUntil(() => false); return 0;"); + + [Fact] + public void Rejects_Monitor() + => Rejects("var o = new object(); System.Threading.Monitor.Enter(o); return 0;"); + + [Fact] + public void Rejects_named_Mutex_system_global_kernel_object() + => Rejects("using var m = new System.Threading.Mutex(false, \"Global\\\\otopcua\"); return 0;"); + + [Fact] + public void Rejects_ManualResetEventSlim() + => Rejects("var e = new System.Threading.ManualResetEventSlim(false); e.Wait(); return 0;"); + + [Fact] + public void Rejects_EventWaitHandle() + => Rejects("var e = new System.Threading.EventWaitHandle(false, System.Threading.EventResetMode.ManualReset); return 0;"); + + [Fact] + public void Rejects_Thread_ThreadPool_and_Timer_still() + { + Rejects("var t = new System.Threading.Thread(() => { }); return 0;"); + Rejects("System.Threading.ThreadPool.QueueUserWorkItem(_ => { }); return 0;"); + Rejects("var t = new System.Threading.Timer(_ => { }); return 0;"); + } + + [Fact] + public void Rejects_Thread_Sleep() + => Rejects("System.Threading.Thread.Sleep(10); return 0;"); + + // ── the allow-list inside System.Threading ─────────────────────────────────────────────── + + [Fact] + public async Task Allows_CancellationToken() + { + using var ev = ScriptEvaluator.Compile( + "var t = System.Threading.CancellationToken.None; return t.IsCancellationRequested ? 1 : 0;"); + (await ev.RunAsync(new FakeScriptContext(), TestContext.Current.CancellationToken)).ShouldBe(0); + } + + [Fact] + public async Task Allows_Interlocked() + { + using var ev = ScriptEvaluator.Compile( + "var x = 41; System.Threading.Interlocked.Increment(ref x); return x;"); + (await ev.RunAsync(new FakeScriptContext(), TestContext.Current.CancellationToken)).ShouldBe(42); + } + + [Fact] + public async Task Allows_Volatile() + { + using var ev = ScriptEvaluator.Compile( + "var x = 42; return System.Threading.Volatile.Read(ref x);"); + (await ev.RunAsync(new FakeScriptContext(), TestContext.Current.CancellationToken)).ShouldBe(42); + } + + // ── System.Type reflection entry points ────────────────────────────────────────────────── + + [Fact] + public void Rejects_Type_GetType_by_name() + { + var ex = Rejects("var t = System.Type.GetType(\"System.IO.File\"); return t is null ? 0 : 1;"); + ex.Rejections.ShouldContain(r => r.Message.Contains("GetType")); + } + + [Fact] + public void Rejects_Type_GetMethod() + => Rejects("var m = typeof(string).GetMethod(\"Trim\"); return m is null ? 0 : 1;"); + + [Fact] + public void Rejects_Type_GetMethods() + => Rejects("return typeof(string).GetMethods().Length;"); + + [Fact] + public void Rejects_Type_InvokeMember() + => Rejects("""return (int)typeof(string).InvokeMember("Length", System.Reflection.BindingFlags.GetProperty, null, "abc", null)!;"""); + + [Fact] + public void Rejects_Type_GetProperty_GetField_GetMember_GetConstructor_GetEvent() + { + Rejects("return typeof(string).GetProperty(\"Length\") is null ? 0 : 1;"); + Rejects("return typeof(string).GetField(\"Empty\") is null ? 0 : 1;"); + Rejects("return typeof(string).GetMember(\"Length\").Length;"); + Rejects("return typeof(string).GetConstructors().Length;"); + Rejects("return typeof(string).GetEvent(\"x\") is null ? 0 : 1;"); + } + + [Fact] + public async Task Allows_instance_GetType_and_Type_metadata_reads() + { + // object.GetType() is declared on System.Object, and Type.Name / IsValueType are plain metadata + // reads — neither is a reflection entry point, and both are common in authored scripts. + using var ev = ScriptEvaluator.Compile( + "object o = 42; var t = o.GetType(); return t.IsValueType && typeof(int).Name == \"Int32\" ? 1 : 0;"); + (await ev.RunAsync(new FakeScriptContext(), TestContext.Current.CancellationToken)).ShouldBe(1); + } + + // ── RuntimeHelpers ─────────────────────────────────────────────────────────────────────── + + [Fact] + public void Rejects_RuntimeHelpers() + { + var ex = Rejects( + "var o = System.Runtime.CompilerServices.RuntimeHelpers.GetUninitializedObject(typeof(string)); return o is null ? 0 : 1;"); + ex.Rejections.ShouldContain(r => r.TypeName.Contains("RuntimeHelpers")); + } + + [Fact] + public async Task Allows_compile_time_only_CompilerServices_attributes() + { + // The namespace stays open for the harmless compile-time types (MethodImplOptions etc.). + using var ev = ScriptEvaluator.Compile( + "var o = System.Runtime.CompilerServices.MethodImplOptions.NoInlining; return (int)o;"); + (await ev.RunAsync(new FakeScriptContext(), TestContext.Current.CancellationToken)).ShouldBe(8); + } +} diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverRemediationTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverRemediationTests.cs new file mode 100644 index 00000000..0372ea15 --- /dev/null +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverRemediationTests.cs @@ -0,0 +1,189 @@ +using System.Collections.Concurrent; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Serilog; +using Serilog.Events; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging; +using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; + +namespace ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests; + +/// +/// Review 07 Calculation remediation: a compile failure is negative-cached by source hash and its +/// Warning/script-log fires on the Good→Bad transition only (P4); inputs are recorded before +/// InitializeAsync so a Restart computes from current inputs (H6); array results dedup +/// structurally (H8); ShutdownAsync drops the compiled scripts (L2). +/// +public sealed class CalculationDriverRemediationTests +{ + private const uint StatusGood = 0u; + private const uint StatusBadInternalError = 0x80020000u; + + private static RawTagEntry CalcTag(string rawPath, string source, bool changeTriggered = true, int? timerMs = null) + { + var timer = timerMs is { } ms ? $",\"timerIntervalMs\":{ms}" : ""; + var json = $"{{\"scriptId\":\"s-{rawPath}\",\"changeTriggered\":{(changeTriggered ? "true" : "false")}{timer}," + + $"\"scriptSource\":{System.Text.Json.JsonSerializer.Serialize(source)}}}"; + return new RawTagEntry(rawPath, json, WriteIdempotent: false); + } + + private static (CalculationDriver Driver, ConcurrentQueue Published, List Logs, CapturingLogger HostLog) + Build(params RawTagEntry[] tags) + { + var logs = new List(); + var sink = new ScriptLogTopicSink(new CapturingPublisher(logs), LogEventLevel.Information); + var scriptRoot = new ScriptRootLogger(new LoggerConfiguration().WriteTo.Sink(sink).CreateLogger()); + var hostLog = new CapturingLogger(); + var driver = new CalculationDriver(new CalculationDriverOptions { RawTags = tags }, "calc-drv", scriptRoot, hostLog); + var published = new ConcurrentQueue(); + driver.OnDataChange += (_, e) => published.Enqueue(e); + return (driver, published, logs, hostLog); + } + + private static async Task Settle(CalculationDriver driver) + { + var deadline = DateTime.UtcNow.AddSeconds(30); + while (!driver.IsEvaluationIdle && DateTime.UtcNow < deadline) await Task.Delay(10); + driver.IsEvaluationIdle.ShouldBeTrue("the calc driver's evaluation pump should have drained"); + } + + /// Fix round 1 minor: Dispose releases the evaluation gate and its cancellation source — even + /// with a runaway run in flight (the guard lets the caller's cancel win, so the awaited run returns + /// promptly) — and a trigger arriving after Dispose is harmless. + [Fact] + public async Task Dispose_with_a_run_in_flight_disposes_the_eval_gate_and_a_late_trigger_is_harmless() + { + var (driver, _, _, _) = Build( + CalcTag("calc/e/spin", "var v = ctx.GetTag(\"src/a\").Value; var end = System.DateTime.UtcNow.AddSeconds(6); while (System.DateTime.UtcNow < end) { } return 1;")); + await driver.InitializeAsync("{}", TestContext.Current.CancellationToken); + driver.OnDependencyValue("src/a", 1, StatusGood, DateTime.UtcNow); + var deadline = DateTime.UtcNow.AddSeconds(10); + while (driver.IsEvaluationIdle && DateTime.UtcNow < deadline) await Task.Delay(5); + driver.IsEvaluationIdle.ShouldBeFalse("positive control: a run is in flight when Dispose lands"); + + var sw = System.Diagnostics.Stopwatch.StartNew(); + driver.Dispose(); + sw.Elapsed.ShouldBeLessThan(TimeSpan.FromSeconds(5), "the caller's cancel releases the awaited run; Dispose is not held for the 6 s spin"); + driver.EvalResourcesDisposedForTest.ShouldBeTrue(); + + Should.NotThrow(() => driver.OnDependencyValue("src/a", 2, StatusGood, DateTime.UtcNow)); + Should.NotThrow(() => driver.Dispose()); + } + + [Fact] + public async Task A_compile_failure_is_remembered_and_logged_once_across_repeated_triggers() + { + var (driver, published, logs, hostLog) = Build( + CalcTag("calc/e/broken", "var x = (double)ctx.GetTag(\"src/a\").Value; this is not valid C#;")); + await driver.InitializeAsync("{}", TestContext.Current.CancellationToken); + + for (var i = 0; i < 5; i++) + { + driver.OnDependencyValue("src/a", i, StatusGood, DateTime.UtcNow); + await Settle(driver); + } + + published.Count.ShouldBe(1, "Bad is published once per transition"); + published.TryDequeue(out var bad).ShouldBeTrue(); + bad!.Snapshot.StatusCode.ShouldBe(StatusBadInternalError); + logs.Count.ShouldBe(1, "the script-log entry fires on the Good→Bad transition only"); + hostLog.Entries.Count(e => e.Level == LogLevel.Warning && e.Message.Contains("compile failed")).ShouldBe(1, + "Roslyn is consulted once per source; later triggers hit the negative cache"); + driver.CompileFailureCountForTest.ShouldBe(1); + } + + [Fact] + public async Task A_changed_failure_reason_is_logged_even_while_already_Bad() + { + // Throws with a different message depending on the input, so the failure REASON changes while the + // published status stays Bad — the operator must see the new reason. + var (driver, published, logs, _) = Build( + CalcTag("calc/e/thrower", "throw new System.InvalidOperationException(\"boom \" + (int)ctx.GetTag(\"src/a\").Value);")); + await driver.InitializeAsync("{}", TestContext.Current.CancellationToken); + + driver.OnDependencyValue("src/a", 1, StatusGood, DateTime.UtcNow); + await Settle(driver); + driver.OnDependencyValue("src/a", 1, StatusGood, DateTime.UtcNow); // same reason → no new log + await Settle(driver); + driver.OnDependencyValue("src/a", 2, StatusGood, DateTime.UtcNow); // new reason → logged + await Settle(driver); + + published.Count.ShouldBe(1); + logs.Count.ShouldBe(2); + logs[0].Message.ShouldContain("boom 1"); + logs[1].Message.ShouldContain("boom 2"); + } + + [Fact] + public async Task Inputs_delivered_before_InitializeAsync_are_kept_so_the_first_trigger_computes() + { + // H6: a Restart is a new driver whose adapter registers interest at construction; the mux's + // retained-value replay therefore lands BEFORE InitializeAsync. It used to be dropped. + var (driver, published, _, _) = Build( + CalcTag("calc/e/sum", "return (double)ctx.GetTag(\"src/a\").Value + (double)ctx.GetTag(\"src/b\").Value;")); + + driver.OnDependencyValue("src/a", 10.0, StatusGood, DateTime.UtcNow); // replayed, pre-init + driver.OnDependencyValue("src/b", 20.0, StatusGood, DateTime.UtcNow); + published.ShouldBeEmpty("evaluation is gated on running"); + + await driver.InitializeAsync("{}", TestContext.Current.CancellationToken); + driver.OnDependencyValue("src/a", 12.0, StatusGood, DateTime.UtcNow); // only ONE input moves after init + await Settle(driver); + + published.Count.ShouldBe(1, "src/b's pre-init value satisfied the change-gate"); + published.TryDequeue(out var e).ShouldBeTrue(); + e!.Snapshot.Value.ShouldBe(32.0); + } + + [Fact] + public async Task An_equal_array_result_is_deduped_structurally() + { + var (driver, published, _, _) = Build( + CalcTag("calc/e/arr", "var v = (double)ctx.GetTag(\"src/a\").Value; return new double[] { v, v * 2 };")); + await driver.InitializeAsync("{}", TestContext.Current.CancellationToken); + + driver.OnDependencyValue("src/a", 1.0, StatusGood, DateTime.UtcNow); + await Settle(driver); + driver.OnDependencyValue("src/a", 1.0, StatusGood, DateTime.UtcNow); // same array contents + await Settle(driver); + published.Count.ShouldBe(1, "a structurally equal array is not a change"); + + driver.OnDependencyValue("src/a", 2.0, StatusGood, DateTime.UtcNow); + await Settle(driver); + published.Count.ShouldBe(2, "a different array still publishes"); + published.Last().Snapshot.Value.ShouldBe(new double[] { 2.0, 4.0 }); + } + + [Fact] + public async Task ShutdownAsync_drops_the_compiled_scripts() + { + var (driver, published, _, _) = Build(CalcTag("calc/e/x", "return (double)ctx.GetTag(\"src/a\").Value * 2.0;")); + await driver.InitializeAsync("{}", TestContext.Current.CancellationToken); + driver.OnDependencyValue("src/a", 1.0, StatusGood, DateTime.UtcNow); + await Settle(driver); + published.Count.ShouldBe(1); + driver.CompiledScriptCountForTest.ShouldBe(1); + + await driver.ShutdownAsync(TestContext.Current.CancellationToken); + + driver.CompiledScriptCountForTest.ShouldBe(0, "the collectible ALCs must not survive the generation"); + } + + private sealed class CapturingPublisher(List entries) : IScriptLogPublisher + { + public void Publish(ScriptLogEntry entry) { lock (entries) entries.Add(entry); } + } + + internal sealed class CapturingLogger : ILogger + { + public ConcurrentBag<(LogLevel Level, string Message)> Entries { get; } = new(); + public IDisposable? BeginScope(TState state) where TState : notnull => null; + public bool IsEnabled(LogLevel logLevel) => true; + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) + => Entries.Add((logLevel, formatter(state, exception))); + } +} diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverTests.cs index 5eed4c6b..cf22038b 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverTests.cs @@ -229,11 +229,13 @@ public sealed class CalculationDriverTests logs[0].ScriptId.ShouldBe("s-calc/e/div"); logs[0].VirtualTagId.ShouldBe("calc/e/div"); - // a = 0 again → still failing, but NOT a fresh transition → no second Bad publish (script-log still emits). + // a = 0 again → still failing for the SAME reason, NOT a fresh transition → no second Bad publish, + // and (R07:P4) no second script-log entry either: the log fires on the transition or on a change of + // reason, not on every trigger of a tag that is already Bad. driver.OnDependencyValue("src/a", 0, StatusGood, DateTime.UtcNow); await Settle(driver); published.ShouldBeEmpty(); - logs.Count.ShouldBe(2); + logs.Count.ShouldBe(1); // a = 5 → 20 → Good recovery is force-published. driver.OnDependencyValue("src/a", 5, StatusGood, DateTime.UtcNow); diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationEvaluatorRunGuardTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationEvaluatorRunGuardTests.cs new file mode 100644 index 00000000..679e7f71 --- /dev/null +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationEvaluatorRunGuardTests.cs @@ -0,0 +1,87 @@ +using Microsoft.Extensions.Logging.Abstractions; +using Serilog; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; + +namespace ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests; + +/// +/// runs every compiled script through a +/// keyed by calc-tag RawPath. A timed-out run is abandoned on its pool thread; before the guard, every +/// later trigger of the same tag stacked another orphan behind it (one leaked thread per trigger). Now +/// every later trigger is refused ("previous evaluation still running" — Bad, but not a quarantine +/// strike; only consecutive timeouts quarantine), and a healthy sibling on the same evaluator keeps computing. +/// +public sealed class CalculationEvaluatorRunGuardTests +{ + private static ScriptRootLogger NoOpScriptRoot() => new(new LoggerConfiguration().CreateLogger()); + + /// Outlives the 60 ms budget by a wide margin but still ends, so the orphan frees itself. + private const string SpinScript = + "var end = System.DateTime.UtcNow.AddSeconds(6); while (System.DateTime.UtcNow < end) { } return 0;"; + + private static readonly Dictionary NoDeps = new(); + + [Fact] + public async Task Triggers_during_the_previous_orphan_are_refused_not_quarantined_and_a_sibling_keeps_computing() + { + using var sut = new CalculationEvaluator( + NullLogger.Instance, NoOpScriptRoot(), TimeSpan.FromMilliseconds(60)); + var ct = TestContext.Current.CancellationToken; + + var first = await sut.EvaluateAsync("calc/loop", SpinScript, Snap(NoDeps), ct).WaitAsync(TimeSpan.FromSeconds(30), ct); + first.Success.ShouldBeFalse(); + first.Reason.ShouldNotBeNull(); + first.Reason.ShouldContain("timed out"); + + // Every later trigger while the orphan runs is a Bad "previous evaluation still running" — a + // refusal is not a strike, so the tag is NOT quarantined by them (fix round 1, I1). + for (var i = 0; i < 3; i++) + { + var refused = await sut.EvaluateAsync("calc/loop", SpinScript, Snap(NoDeps), ct); + refused.Success.ShouldBeFalse(); + refused.Reason.ShouldBe(ScriptRunGuard.PreviousRunStillRunningReason); + } + sut.QuarantinedScripts.ShouldBeEmpty(); + sut.RunGuard.RefusedWhileRunningCount.ShouldBe(3); + + // Exactly one run was ever dispatched for the runaway tag — the leak is one orphan, not one per trigger. + sut.RunGuard.StartedRunCount.ShouldBe(1); + sut.RunGuard.InFlightCount.ShouldBe(1); + + // Positive control: a sibling tag on the same evaluator still computes. + var sibling = await sut.EvaluateAsync("calc/ok", "return 42;", Snap(NoDeps), ct); + sibling.Success.ShouldBeTrue(sibling.Reason); + sibling.Value.ShouldBe(42); + } + + [Fact] + public async Task ClearCompiledScripts_lifts_the_quarantine_as_a_redeploy_does() + { + using var sut = new CalculationEvaluator( + NullLogger.Instance, NoOpScriptRoot(), TimeSpan.FromMilliseconds(60), + new ScriptingOptions { QuarantineAfterConsecutiveTimeouts = 1 }); + var ct = TestContext.Current.CancellationToken; + + var r = await sut.EvaluateAsync("calc/loop", SpinScript, Snap(NoDeps), ct).WaitAsync(TimeSpan.FromSeconds(30), ct); + r.Reason.ShouldNotBeNull(); + r.Reason.ShouldStartWith(ScriptRunGuard.QuarantinedReasonPrefix); + + sut.ClearCompiledScripts(); + + sut.QuarantinedScripts.ShouldBeEmpty(); + // The fixed script (new source) runs; the old orphan is a sunk cost that no longer blocks the tag. + var fixedRun = await sut.EvaluateAsync("calc/loop", "return 7;", Snap(NoDeps), ct); + fixedRun.Success.ShouldBeTrue(fixedRun.Reason); + fixedRun.Value.ShouldBe(7); + } + + private static Dictionary Snap(Dictionary deps) + { + var now = DateTime.UtcNow; + var d = new Dictionary(StringComparer.Ordinal); + foreach (var kv in deps) d[kv.Key] = new Core.Abstractions.DataValueSnapshot(kv.Value, 0u, now, now); + return d; + } +} diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/ScriptAnalysis/DiagnoseTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/ScriptAnalysis/DiagnoseTests.cs index 21460637..94784a45 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/ScriptAnalysis/DiagnoseTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/ScriptAnalysis/DiagnoseTests.cs @@ -31,6 +31,26 @@ public sealed class DiagnoseTests => Diag("""var c = new System.Net.Http.HttpClient(); return 0;""") .ShouldContain(x => x.Severity == 8); + // Sandbox hardening parity (R05:10): the editor runs the SAME ForbiddenTypeAnalyzer the publish gate + // runs, so every newly-denied form must surface as an OTSCRIPT_FORBIDDEN marker here — editor accepts + // ⇔ publish accepts. One case per deny mechanism (namespace, member, type), plus the allow-list. + [Theory] + [InlineData("""new System.Threading.SemaphoreSlim(0).Wait(); return 0;""")] // System.Threading namespace + [InlineData("""System.Threading.SpinWait.SpinUntil(() => false); return 0;""")] + [InlineData("""var t = System.Type.GetType("System.IO.File"); return t is null ? 0 : 1;""")] // forbidden member + [InlineData("""return typeof(string).GetMethods().Length;""")] + [InlineData("""var o = System.Runtime.CompilerServices.RuntimeHelpers.GetUninitializedObject(typeof(string)); return 0;""")] // forbidden type + public void Hardened_sandbox_forms_are_flagged_in_the_editor(string code) + => Diag(code).ShouldContain(x => x.Code == "OTSCRIPT_FORBIDDEN" && x.Severity == 8); + + [Theory] + [InlineData("""var t = System.Threading.CancellationToken.None; return t.IsCancellationRequested ? 1 : 0;""")] + [InlineData("""var x = 41; System.Threading.Interlocked.Increment(ref x); return x;""")] + [InlineData("""var x = 42; return System.Threading.Volatile.Read(ref x);""")] + [InlineData("""object o = 42; return o.GetType().IsValueType ? 1 : 0;""")] + public void Allow_listed_forms_are_not_flagged_in_the_editor(string code) + => Diag(code).ShouldBeEmpty(); + [Fact] public void Dynamic_tag_path_is_flagged() => Diag("""var p = "A"; return ctx.GetTag(p).Value;""") .ShouldContain(x => x.Message.Contains("literal")); diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorRunGuardTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorRunGuardTests.cs new file mode 100644 index 00000000..cd18ae5e --- /dev/null +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorRunGuardTests.cs @@ -0,0 +1,64 @@ +using Microsoft.Extensions.Logging.Abstractions; +using Serilog; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; +using ZB.MOM.WW.OtOpcUa.Host.Engines; + +namespace ZB.MOM.WW.OtOpcUa.Host.IntegrationTests; + +/// +/// runs every compiled expression through a +/// keyed by virtual-tag id: a runaway expression leaks one orphaned pool +/// thread, not one per trigger, later triggers are refused, the tag is quarantined after three consecutive timeouts (surfacing +/// as a Failure the actor publishes Bad for), and the quarantine lifts at the deploy boundary. +/// +public sealed class RoslynVirtualTagEvaluatorRunGuardTests +{ + private static ScriptRootLogger NoOpScriptRoot() => new(new LoggerConfiguration().CreateLogger()); + + private const string SpinScript = + "var end = System.DateTime.UtcNow.AddSeconds(6); while (System.DateTime.UtcNow < end) { } return 0;"; + + private static readonly Dictionary NoDeps = new(); + + [Fact] + public void Runaway_expression_is_refused_while_its_orphan_runs_and_a_sibling_keeps_evaluating() + { + using var sut = new RoslynVirtualTagEvaluator( + NullLogger.Instance, NoOpScriptRoot(), TimeSpan.FromMilliseconds(60)); + + var first = sut.Evaluate("vt-loop", SpinScript, NoDeps); + first.Success.ShouldBeFalse(); + first.Reason.ShouldNotBeNull(); + first.Reason.ShouldContain("timed out"); + + // Refusals, not strikes (fix round 1, I1): the tag stays Bad but is not quarantined by them. + sut.Evaluate("vt-loop", SpinScript, NoDeps).Reason.ShouldBe(ScriptRunGuard.PreviousRunStillRunningReason); + sut.Evaluate("vt-loop", SpinScript, NoDeps).Reason.ShouldBe(ScriptRunGuard.PreviousRunStillRunningReason); + sut.QuarantinedScripts.ShouldBeEmpty(); + sut.RunGuard.StartedRunCount.ShouldBe(1, "one orphan, not one per trigger"); + + var sibling = sut.Evaluate("vt-ok", "return 42;", NoDeps); + sibling.Success.ShouldBeTrue(sibling.Reason); + sibling.Value.ShouldBe(42); + } + + [Fact] + public void ResetQuarantines_lifts_the_quarantine_as_a_redeploy_does() + { + using var sut = new RoslynVirtualTagEvaluator( + NullLogger.Instance, NoOpScriptRoot(), TimeSpan.FromMilliseconds(60), + new ScriptingOptions { QuarantineAfterConsecutiveTimeouts = 1 }); + + sut.Evaluate("vt-loop", SpinScript, NoDeps).Reason!.ShouldStartWith(ScriptRunGuard.QuarantinedReasonPrefix); + sut.QuarantinedScripts.ShouldNotBeEmpty(); + + sut.ResetQuarantines(); + + sut.QuarantinedScripts.ShouldBeEmpty(); + var fixedRun = sut.Evaluate("vt-loop", "return 7;", NoDeps); + fixedRun.Success.ShouldBeTrue(fixedRun.Reason); + fixedRun.Value.ShouldBe(7); + } +} diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs index 004b7165..47ac617a 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs @@ -489,12 +489,18 @@ public sealed class RoslynVirtualTagEvaluatorTests // most evaluations then hit the warm cache instead of recompiling. Neither the cadence nor the // iteration count is a correctness knob any more — the assertions below hold for any number of // clears landing inside a single evaluation, and for any number of evaluations completed. - var evalLoops = Enumerable.Range(0, loopCount).Select(_ => Task.Run(() => + // One virtual-tag id PER LOOP, sharing the expression. The race under test lives in the compile + // cache, which is keyed by source, so twelve ids on one expression contend for exactly the entry + // twelve copies of one id did — while twelve concurrent evaluations of ONE id is a shape production + // never produces (one VirtualTagActor per id serialises them) and exactly the shape the per-tag + // ScriptRunGuard refuses ("previous evaluation still running", then quarantine). + var evalLoops = Enumerable.Range(0, loopCount).Select(loop => Task.Run(() => { + var vtagId = $"vt-race-{loop}"; var done = 0; for (var i = 0; i < MaxIterationsPerLoop && Environment.TickCount64 < stopAtMs; i++) { - var r = sut.Evaluate("vt-race", expr, new Dictionary { ["a"] = i }); + var r = sut.Evaluate(vtagId, expr, new Dictionary { ["a"] = i }); done++; if (!r.Success) { diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/ScriptedAlarms/DependencyMuxTagUpstreamSourceTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/ScriptedAlarms/DependencyMuxTagUpstreamSourceTests.cs index d020d118..a3861648 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/ScriptedAlarms/DependencyMuxTagUpstreamSourceTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/ScriptedAlarms/DependencyMuxTagUpstreamSourceTests.cs @@ -15,6 +15,28 @@ public sealed class DependencyMuxTagUpstreamSourceTests private static DataValueSnapshot Good(object? value, DateTime ts) => new(value, 0u, ts, ts); + /// R02:L3 — the host prunes the retained snapshots to the loaded dependency-ref union after each + /// (re)load, so a renamed/removed raw path stops being retained; observers are untouched. + [Fact] + public void RetainOnly_drops_snapshots_outside_the_set_and_keeps_observers() + { + var src = new DependencyMuxTagUpstreamSource(); + var ts = DateTime.UtcNow; + src.Push("keep", Good(1, ts)); + src.Push("old/renamed", Good(2, ts)); + var seen = new List(); + using var sub = src.SubscribeTag("old/renamed", (p, _) => seen.Add(p)); + + src.RetainOnly(new HashSet(StringComparer.Ordinal) { "keep" }).ShouldBe(1); + + src.RetainedPathCount.ShouldBe(1); + src.ReadTag("keep").Value.ShouldBe(1); + src.ReadTag("old/renamed").StatusCode.ShouldBe(OpcUaStatus.BadWaitingForInitialData); + src.Push("old/renamed", Good(3, ts)); + // Pruning retained values does not unsubscribe anyone. + seen.ShouldBe(new[] { "old/renamed" }); + } + [Fact] public void Push_then_ReadTag_returns_the_pushed_snapshot() { diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/ScriptedAlarms/ScriptedAlarmHostActorRestartTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/ScriptedAlarms/ScriptedAlarmHostActorRestartTests.cs new file mode 100644 index 00000000..c4063d57 --- /dev/null +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/ScriptedAlarms/ScriptedAlarmHostActorRestartTests.cs @@ -0,0 +1,145 @@ +using Akka.Actor; +using Akka.TestKit; +using Serilog; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Commons.OpcUa; +using ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; +using ZB.MOM.WW.OtOpcUa.OpcUaServer; +using ZB.MOM.WW.OtOpcUa.Runtime.OpcUa; +using ZB.MOM.WW.OtOpcUa.Runtime.ScriptedAlarms; +using ZB.MOM.WW.OtOpcUa.Runtime.Tests.Harness; +using ZB.MOM.WW.OtOpcUa.Runtime.VirtualTags; + +namespace ZB.MOM.WW.OtOpcUa.Runtime.Tests.ScriptedAlarms; + +/// +/// R02:H1 — a supervision restart of used to dispose the +/// Props-captured engine and re-create the actor around the disposed instance, so every later +/// ApplyScriptedAlarms failed and the node's scripted alarms silently died. With the factory +/// Props each incarnation builds its own engine; with the legacy Props a restart only detaches. Both +/// shapes must load cleanly after a throw inside a +/// handler. Also R02:H3 — an inbound alarm command's engine op is bounded. +/// +public sealed class ScriptedAlarmHostActorRestartTests : RuntimeActorTestBase +{ + private static readonly TimeSpan Timeout = TimeSpan.FromSeconds(30); + + private static EquipmentScriptedAlarmPlan Plan(string id = "alm-1", string depRef = "M.T") => + new(ScriptedAlarmId: id, EquipmentId: "Plant/Line1/M", Name: "HighTemp", AlarmType: "AlarmCondition", + Severity: 800, MessageTemplate: "condition", PredicateScriptId: $"{id}-script", + PredicateSource: $"return (int)ctx.GetTag(\"{depRef}\").Value > 90;", + DependencyRefs: new[] { depRef }, HistorizeToAveva: true, Retain: true, Enabled: true); + + private static ScriptedAlarmEngine BuildEngine(DependencyMuxTagUpstreamSource upstream, IAlarmStateStore? store = null) + { + var logger = new LoggerConfiguration().CreateLogger(); + return new ScriptedAlarmEngine(upstream, store ?? new InMemoryAlarmStateStore(), new ScriptLoggerFactory(logger), logger); + } + + private static (DependencyMuxTagUpstreamSource, ScriptedAlarmEngine) Pair() + { + var up = new DependencyMuxTagUpstreamSource(); + return (up, BuildEngine(up)); + } + + /// Apply, crash the handler (a null TagId makes Push throw → restart), apply again + /// and prove the second load registers interest and the alarm still activates. + private void RestartThenReload(IActorRef host, TestProbe publish, TestProbe mux) + { + host.Tell(new ScriptedAlarmHostActor.ApplyScriptedAlarms(new[] { Plan() })); + mux.ExpectMsg(Timeout); + + // The crash: a batch whose item has a null TagId makes the upstream Push throw out of the handler + // (the documented, deliberately unguarded path) → supervision restarts the actor. + host.Tell(new VirtualTagActor.DependencyValueBatch(new[] + { + new VirtualTagActor.DependencyValueChanged(null!, 1, DateTime.UtcNow), + })); + mux.ExpectMsg(Timeout); // PostStop of the crashed incarnation + + // A later apply must load cleanly on the restarted incarnation… + host.Tell(new ScriptedAlarmHostActor.ApplyScriptedAlarms(new[] { Plan() })); + var reg = mux.ExpectMsg(Timeout); + reg.TagRefs.ShouldContain("M.T"); + + // …and the alarm must still work end to end. + host.Tell(new VirtualTagActor.DependencyValueChanged("M.T", 99, DateTime.UtcNow)); + var state = publish.ExpectMsg(Timeout); + state.AlarmNodeId.ShouldBe("alm-1"); + state.State.Active.ShouldBeTrue(); + } + + [Fact] + public void Factory_Props_survives_a_handler_throw_and_loads_cleanly_afterwards() + { + var publish = CreateTestProbe(); + var mux = CreateTestProbe(); + var built = 0; + var host = Sys.ActorOf(ScriptedAlarmHostActor.Props(publish.Ref, mux.Ref, () => { built++; return Pair(); })); + + RestartThenReload(host, publish, mux); + + built.ShouldBe(2, "the restarted incarnation built its own engine"); + } + + [Fact] + public void Legacy_instance_Props_survives_a_handler_throw_because_a_restart_only_detaches() + { + var publish = CreateTestProbe(); + var mux = CreateTestProbe(); + var (upstream, engine) = Pair(); + var host = Sys.ActorOf(ScriptedAlarmHostActor.Props(publish.Ref, mux.Ref, upstream, engine)); + + RestartThenReload(host, publish, mux); + } + + [Fact] + public void An_alarm_command_whose_store_hangs_is_bounded_and_the_mailbox_moves_on() + { + var publish = CreateTestProbe(); + var mux = CreateTestProbe(); + var store = new HangingSaveStore(); + var host = Sys.ActorOf(ScriptedAlarmHostActor.Props(publish.Ref, mux.Ref, + () => { var up = new DependencyMuxTagUpstreamSource(); return (up, BuildEngine(up, store)); }, + commandTimeout: TimeSpan.FromMilliseconds(300))); + + host.Tell(new ScriptedAlarmHostActor.ApplyScriptedAlarms(new[] { Plan() })); + mux.ExpectMsg(Timeout); + host.Tell(new VirtualTagActor.DependencyValueChanged("M.T", 99, DateTime.UtcNow)); + publish.ExpectMsg(Timeout).State.Active.ShouldBeTrue(); + + store.HangNext = true; + host.Tell(new AlarmCommand("alm-1", "Acknowledge", "alice", "ack", null)); + + // The hung save would have suspended the mailbox indefinitely; the bound releases it, so the + // next dependency value is processed and the alarm clears. + host.Tell(new VirtualTagActor.DependencyValueChanged("M.T", 10, DateTime.UtcNow)); + publish.ExpectMsg(Timeout).State.Active.ShouldBeFalse(); + store.ObservedCancellation.ShouldBeTrue(); + } + + /// Store whose next SaveAsync blocks until its token is cancelled. + private sealed class HangingSaveStore : IAlarmStateStore + { + private readonly InMemoryAlarmStateStore _inner = new(); + public volatile bool HangNext; + public volatile bool ObservedCancellation; + + public Task LoadAsync(string alarmId, CancellationToken ct) => _inner.LoadAsync(alarmId, ct); + public Task> LoadAllAsync(CancellationToken ct) => _inner.LoadAllAsync(ct); + public Task RemoveAsync(string alarmId, CancellationToken ct) => _inner.RemoveAsync(alarmId, ct); + + public async Task SaveAsync(AlarmConditionState state, CancellationToken ct) + { + if (HangNext) + { + HangNext = false; + try { await Task.Delay(System.Threading.Timeout.InfiniteTimeSpan, ct); } + catch (OperationCanceledException) { ObservedCancellation = true; throw; } + } + await _inner.SaveAsync(state, ct); + } + } +} diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/DependencyMuxReplayTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/DependencyMuxReplayTests.cs new file mode 100644 index 00000000..f761edd9 --- /dev/null +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/DependencyMuxReplayTests.cs @@ -0,0 +1,184 @@ +using System.Collections.Concurrent; +using Akka.Actor; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Commons.OpcUa; +using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Driver.Calculation; +using ZB.MOM.WW.OtOpcUa.Runtime.Drivers; +using ZB.MOM.WW.OtOpcUa.Runtime.Tests.Harness; +using ZB.MOM.WW.OtOpcUa.Runtime.VirtualTags; + +namespace ZB.MOM.WW.OtOpcUa.Runtime.Tests.VirtualTags; + +/// +/// R07:H6 — the mux retains the last value of every ref a REPLAY-OPTING subscriber +/// () is registered for, keeps it for a +/// short grace after the last such subscriber leaves, and replays it to a registration that asks. A +/// Calculation driver Restart (new driver + new adapter) therefore republishes from current inputs instead +/// of sitting BadWaitingForInitialData until every input happens to change. Fix round 1 (I2): a +/// non-opting subscriber (the historization recorder) retains nothing, retention is released after the +/// grace, and a removed source's values are evicted so its last Good is never replayed. +/// +public sealed class DependencyMuxReplayTests : RuntimeActorTestBase +{ + private static DriverInstanceActor.AttributeValueBatchPublished Burst(params (string Ref, object? Value)[] items) => + new("driver-1", items.Select(i => new DriverInstanceActor.AttributeValueItem(i.Ref, i.Value, OpcUaStatus.Good, DateTime.UtcNow)).ToArray()); + + [Fact] + public void RegisterInterest_with_replay_receives_the_retained_values_for_its_refs_only() + { + var mux = Sys.ActorOf(DependencyMuxActor.Props()); + var first = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "a", "b" }, first.Ref, ReplayRetained: true)); + mux.Tell(Burst(("a", 1), ("b", 2), ("c", 3))); + first.ExpectMsg(PresenceBudget).Items.Count.ShouldBe(2); + + // The first subscriber goes away; retention must survive the unregister (that is the Restart shape). + mux.Tell(new DependencyMuxActor.UnregisterInterest(first.Ref)); + + var second = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "a", "c" }, second.Ref, ReplayRetained: true)); + + var replay = second.ExpectMsg(PresenceBudget); + replay.Items.Select(i => i.TagId).ShouldBe(new[] { "a" }, "'c' was never registered by a replay-opting subscriber, so it is not retained; 'b' is not in this subscriber's refs"); + replay.Items[0].Value.ShouldBe(1); + } + + [Fact] + public void RegisterInterest_without_replay_receives_nothing_and_a_fresh_ref_replays_nothing() + { + var mux = Sys.ActorOf(DependencyMuxActor.Props()); + var seed = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "a" }, seed.Ref)); + mux.Tell(Burst(("a", 1))); + seed.ExpectMsg(PresenceBudget); + + var opted = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "a" }, opted.Ref)); // default: no replay + opted.ExpectNoMsg(TimeSpan.FromMilliseconds(300)); + + var fresh = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "never-published" }, fresh.Ref, ReplayRetained: true)); + fresh.ExpectNoMsg(TimeSpan.FromMilliseconds(300)); + } + + /// I2 — a subscriber that did NOT opt into replay (the continuous-historization recorder registers + /// every historized ref) retains nothing; retention is bounded to the refs a replay-opting subscriber named. + [Fact] + public void Only_refs_named_by_a_replay_opting_subscriber_are_retained() + { + var mux = ActorOfAsTestActorRef(DependencyMuxActor.Props()); + var recorder = CreateTestProbe(); + var calc = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "h1", "h2", "h3", "shared" }, recorder.Ref)); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "r", "shared" }, calc.Ref, ReplayRetained: true)); + mux.Tell(Burst(("h1", 1), ("h2", 2), ("h3", 3), ("r", 4), ("shared", 5))); + recorder.ExpectMsg(PresenceBudget).Items.Count.ShouldBe(4, "the recorder is still DELIVERED to"); + calc.ExpectMsg(PresenceBudget); + + mux.UnderlyingActor.RetainedRefCount.ShouldBe(2, "only 'r' and 'shared' — the recorder-only refs retain nothing"); + + var late = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "h1", "r" }, late.Ref, ReplayRetained: true)); + late.ExpectMsg(PresenceBudget) + .Items.Select(i => i.TagId).ShouldBe(new[] { "r" }, "positive control: the opted-in ref replays; 'h1' was never retained"); + + // Unregistering everyone ends up with no entries at all once the grace is over — tested below; here + // the recorder leaving changes nothing about retention. + mux.Tell(new DependencyMuxActor.UnregisterInterest(recorder.Ref)); + mux.UnderlyingActor.RetainedRefCount.ShouldBe(2); + } + + /// I2 — when the last replay-opting subscriber of a ref leaves, its retained value survives a short + /// grace (the restart window: old adapter gone, new one not yet registered) and is then dropped. + [Fact] + public void Retention_is_released_after_the_grace_once_no_replay_subscriber_remains() + { + var mux = ActorOfAsTestActorRef(DependencyMuxActor.Props(TimeSpan.FromMilliseconds(200))); + var gen1 = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "a" }, gen1.Ref, ReplayRetained: true)); + mux.Tell(Burst(("a", 1))); + gen1.ExpectMsg(PresenceBudget); + mux.Tell(new DependencyMuxActor.UnregisterInterest(gen1.Ref)); + + // Positive control: inside the grace a returning subscriber still gets the value. + var gen2 = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "a" }, gen2.Ref, ReplayRetained: true)); + gen2.ExpectMsg(PresenceBudget).Items.Single().Value.ShouldBe(1); + mux.Tell(new DependencyMuxActor.UnregisterInterest(gen2.Ref)); + + // Past the grace: nothing retained, no entry left behind, and a returning subscriber replays nothing. + AwaitAssert(() => + { + mux.UnderlyingActor.RetainedRefCount.ShouldBe(0); + mux.UnderlyingActor.TrackedRefCount.ShouldBe(0); + }, PresenceBudget); + var gen3 = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "a" }, gen3.Ref, ReplayRetained: true)); + gen3.ExpectNoMsg(TimeSpan.FromMilliseconds(300)); + } + + /// I2 — a removed source's retained values are evicted, so its last Good is never replayed to a + /// subscriber that (re)registers after the removal. Values from other sources are untouched. + [Fact] + public void SourceRemoved_evicts_that_sources_retained_values_only() + { + var mux = ActorOfAsTestActorRef(DependencyMuxActor.Props()); + var sub = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "a", "b" }, sub.Ref, ReplayRetained: true)); + mux.Tell(new DriverInstanceActor.AttributeValueBatchPublished("driver-1", + [new DriverInstanceActor.AttributeValueItem("a", 1, OpcUaStatus.Good, DateTime.UtcNow)])); + mux.Tell(new DriverInstanceActor.AttributeValueBatchPublished("driver-2", + [new DriverInstanceActor.AttributeValueItem("b", 2, OpcUaStatus.Good, DateTime.UtcNow)])); + sub.ExpectMsg(PresenceBudget); + sub.ExpectMsg(PresenceBudget); + + mux.Tell(new DependencyMuxActor.SourceRemoved("driver-1")); + mux.UnderlyingActor.RetainedRefCount.ShouldBe(1); + + var restarted = CreateTestProbe(); + mux.Tell(new DependencyMuxActor.RegisterInterest(new[] { "a", "b" }, restarted.Ref, ReplayRetained: true)); + restarted.ExpectMsg(PresenceBudget) + .Items.Select(i => i.TagId).ShouldBe(new[] { "b" }, "driver-1 was removed: its last Good must not be replayed"); + } + + /// The user-facing scenario: a calc tag computes, the driver is restarted (new instance + new + /// adapter) with NO input changing afterwards, and the new instance republishes the current value. + [Fact] + public async Task A_Calculation_driver_restart_republishes_from_the_current_inputs() + { + var mux = Sys.ActorOf(DependencyMuxActor.Props()); + var tag = new RawTagEntry("calc/e/sum", + "{\"scriptId\":\"s\",\"changeTriggered\":true,\"scriptSource\":\"return (double)ctx.GetTag(\\\"src/a\\\").Value + (double)ctx.GetTag(\\\"src/b\\\").Value;\"}", + WriteIdempotent: false); + + // Generation 1: wire the driver through the real adapter and feed a burst. + var gen1 = new CalculationDriver(new CalculationDriverOptions { RawTags = [tag] }, "calc-drv"); + var published1 = new ConcurrentQueue(); + gen1.OnDataChange += (_, e) => published1.Enqueue(e); + await gen1.InitializeAsync("{}", CancellationToken.None); + var adapter1 = Sys.ActorOf(DependencyConsumerMuxAdapter.Props(gen1, mux)); + AwaitAssert(() => + { + mux.Tell(Burst(("src/a", 10.0), ("src/b", 20.0))); + published1.Count.ShouldBeGreaterThan(0); + }, PresenceBudget); + published1.Last().Snapshot.Value.ShouldBe(30.0); + + // Restart: the old instance goes away; a NEW driver + adapter come up. Nothing changes upstream. + Sys.Stop(adapter1); + await gen1.ShutdownAsync(CancellationToken.None); + var gen2 = new CalculationDriver(new CalculationDriverOptions { RawTags = [tag] }, "calc-drv"); + var published2 = new ConcurrentQueue(); + gen2.OnDataChange += (_, e) => published2.Enqueue(e); + Sys.ActorOf(DependencyConsumerMuxAdapter.Props(gen2, mux)); // registers with ReplayRetained + await gen2.InitializeAsync("{}", CancellationToken.None); + + // The replayed inputs satisfied the change-gate; the first trigger after init is the replay itself + // (if it lands post-init) or the next change (here: none) — so publish happens from the replay. + AwaitAssert(() => published2.Count.ShouldBeGreaterThan(0), PresenceBudget); + published2.Last().Snapshot.Value.ShouldBe(30.0); + published2.Last().Snapshot.StatusCode.ShouldBe(OpcUaStatus.Good); + } +} diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/VirtualTagActorFailureLogRateLimitTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/VirtualTagActorFailureLogRateLimitTests.cs new file mode 100644 index 00000000..c1a6253e --- /dev/null +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/VirtualTagActorFailureLogRateLimitTests.cs @@ -0,0 +1,56 @@ +using System.Collections.Concurrent; +using Akka.Actor; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Commons.Engines; +using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; +using ZB.MOM.WW.OtOpcUa.Runtime.Tests.Harness; +using ZB.MOM.WW.OtOpcUa.Runtime.VirtualTags; + +namespace ZB.MOM.WW.OtOpcUa.Runtime.Tests.VirtualTags; + +/// R02:P6 — the per-failure cluster-wide is rate-limited per tag +/// (first N per window, then one summary); the Bad publish and the metric are unaffected. +public sealed class VirtualTagActorFailureLogRateLimitTests : RuntimeActorTestBase +{ + [Fact] + public void Repeated_failures_publish_at_most_the_limit_then_one_summary_when_the_window_rolls() + { + var now = new DateTime(2026, 1, 1, 12, 0, 0, DateTimeKind.Utc); + var limiter = new ScriptLogRateLimiter(limitPerWindow: 3, window: TimeSpan.FromMinutes(1), clock: () => now); + var capture = new ConcurrentQueue(); + var parent = CreateTestProbe(); + var actor = parent.ChildActorOf(VirtualTagActor.Props( + "vt-chatty", "broken", + evaluator: new FailingEvaluator("boom"), + publisherFactory: () => new DPSPublisher((_, p) => capture.Enqueue((ScriptLogEntry)p)), + failureLogLimiter: limiter)); + + for (var i = 0; i < 10; i++) + actor.Tell(new VirtualTagActor.DependencyValueChanged("a", i, DateTime.UtcNow)); + + // Positive control: the FIRST failure still degrades the node (once per transition, as before). + parent.ExpectMsg(PresenceBudget).StatusCode.ShouldBe(Commons.OpcUa.OpcUaStatus.BadInternalError); + AwaitAssert(() => capture.Count.ShouldBe(3), PresenceBudget); + parent.ExpectNoMsg(TimeSpan.FromMilliseconds(300)); + capture.Count.ShouldBe(3, "7 of 10 failures were suppressed from the cluster-wide log"); + + now = now.AddMinutes(1); + actor.Tell(new VirtualTagActor.DependencyValueChanged("a", 99, DateTime.UtcNow)); + + AwaitAssert(() => capture.Count.ShouldBe(5), PresenceBudget); + var entries = capture.ToArray(); + entries[3].Message.ShouldContain("7"); + entries[3].Message.ShouldContain("suppressed"); + entries[3].Message.ShouldContain("limit 3/window", Case.Sensitive, "the summary names the CONFIGURED limit, not the default"); + entries[3].VirtualTagId.ShouldBe("vt-chatty"); + entries[4].Message.ShouldBe("boom"); + } + + private sealed class FailingEvaluator(string reason) : IVirtualTagEvaluator + { + public VirtualTagEvalResult Evaluate(string id, string expr, IReadOnlyDictionary deps) + => VirtualTagEvalResult.Failure(reason); + } +}