diff --git a/docs/ScriptEditor.md b/docs/ScriptEditor.md index 41421d34..eb6985e2 100644 --- a/docs/ScriptEditor.md +++ b/docs/ScriptEditor.md @@ -190,9 +190,14 @@ scripted-alarm predicates) runs scripts through the shared `ScriptRunGuard`: 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`. An infinite loop therefore usually shows - as *refused* (one timeout, then refusals for as long as the orphan spins) rather - than *quarantined*. + 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 diff --git a/docs/VirtualTags.md b/docs/VirtualTags.md index 50ef578f..183fcef0 100644 --- a/docs/VirtualTags.md +++ b/docs/VirtualTags.md @@ -34,7 +34,7 @@ User scripts are compiled via `Microsoft.CodeAnalysis.CSharp` (regular compiler, #### Known resource limits (accepted trade-offs) -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). 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". +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". `System.Threading.Tasks` is denied (Core.Scripting-003), which prevents `Task.Run` / `Parallel` fan-out that would spawn background work outliving the timeout. 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 c96c8c87..17b513ac 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms/ScriptedAlarmEngine.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms/ScriptedAlarmEngine.cs @@ -76,7 +76,7 @@ public sealed class ScriptedAlarmEngine : IDisposable /// /// 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) or an allocation-budget breach — one orphan + /// 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; diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs index dc308ce6..de1afee2 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs @@ -1,4 +1,5 @@ using System.Collections.Concurrent; +using System.Diagnostics; using System.Diagnostics.Metrics; using Serilog; using ZB.MOM.WW.OtOpcUa.Commons.Observability; @@ -27,7 +28,10 @@ namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; /// 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): no further dispatch, every attempt throws +/// 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 @@ -63,11 +67,11 @@ public sealed class ScriptRunGuard /// /// Counter otopcua.script.quarantined (Prometheus: otopcua_script_quarantined): one - /// increment per script quarantined, tagged reason = timeouts | allocation. + /// 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 | allocation)."); + 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 @@ -80,6 +84,7 @@ public sealed class ScriptRunGuard 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; @@ -94,6 +99,7 @@ public sealed class ScriptRunGuard options ??= new ScriptingOptions(); _maxAllocBytesPerRun = options.MaxAllocBytesPerRun; _quarantineThreshold = Math.Max(1, options.QuarantineAfterConsecutiveTimeouts); + _stuckFactor = options.StuckOrphanQuarantineFactor; _logger = logger ?? Log.Logger; } @@ -185,6 +191,24 @@ public sealed class ScriptRunGuard // 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); } @@ -200,6 +224,7 @@ public sealed class ScriptRunGuard // 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 @@ -223,6 +248,7 @@ public sealed class ScriptRunGuard // 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(); @@ -339,6 +365,8 @@ public sealed class ScriptRunGuard 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; } @@ -373,7 +401,7 @@ public sealed class ScriptRunRefusedException : Exception /// /// Thrown by for a quarantined script: repeated -/// timeouts or an allocation-budget breach. Nothing is dispatched while quarantined; the seam +/// 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. /// diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptingOptions.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptingOptions.cs index f101a0e1..296d862c 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptingOptions.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptingOptions.cs @@ -25,6 +25,9 @@ public sealed class ScriptingOptions /// 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 @@ -40,4 +43,14 @@ public sealed class ScriptingOptions /// 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/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs index e47cc745..dd7085e3 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs @@ -42,7 +42,7 @@ namespace ZB.MOM.WW.OtOpcUa.Driver.Calculation; /// 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) or an allocation-budget breach — both surface as a +/// 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 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 f0bbd150..8a9347d9 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs @@ -35,7 +35,7 @@ namespace ZB.MOM.WW.OtOpcUa.Host.Engines; /// 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) or an allocation-budget breach. Both surface as +/// 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. diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs index f60045b9..b4efe8af 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs @@ -151,10 +151,13 @@ public sealed class ScriptRunGuardTests } /// - /// The thread-leak regression. 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, every later trigger is refused, and a healthy - /// sibling keeps evaluating throughout (the positive control an absence assertion needs). + /// 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 ( @@ -163,30 +166,37 @@ public sealed class ScriptRunGuardTests /// it must stay far below the 30 the leak would have produced. /// [Fact] - public async Task Runaway_script_leaves_at_most_one_orphan_after_30_triggers_while_a_sibling_keeps_evaluating() + 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); } - catch (ScriptTimeoutException) { } - catch (ScriptRunRefusedException) { } - catch (ScriptQuarantinedException) { } + 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"); - // One timeout + 29 refusals: not quarantined (a refusal is not a strike), but never re-dispatched. - guard.IsQuarantined("runaway", out _).ShouldBeFalse(); - guard.RefusedWhileRunningCount.ShouldBe(29); + 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); @@ -194,6 +204,60 @@ public sealed class ScriptRunGuardTests 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() {