From 105541b6559505f31431831650a3ea4093a509b3 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Sun, 6 Sep 2026 14:22:11 -0400 Subject: [PATCH] fix(site-runtime): shed or rate-limited traced runs emit a Failed ScriptRun row (arch-review F7) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A traced run refused before launch — by the per-script in-flight cap (MaxConcurrentRunsPerScript) or by MinTimeBetweenRuns — emitted no ScriptTrace row at all, so the Flow Debugger reported NO_TRIGGER_WITHIN_WINDOW ("no value-change trigger on this attribute, or no device echo"), which is wrong in both cases and sends the operator to check the wrong things. Both guards now leave a Failed ScriptTrace/ScriptRun row naming the guard that refused the run, parented to the writing execution and carrying the trigger detail. The new ScriptRunLauncher.EmitSuppressedRun reuses EmitScriptRun with elapsedMs 0 and no collector (a shed run has no reply to ride on — the row reaches the debugger via PullTraceEvents / Replay), resolving the writer and identity providers from a fresh scope because it runs on the actor thread. Best-effort, never throws, no-op untraced. Claude-Session: https://claude.ai/code/session_01NcMG6xXdsJbmD2wYAgkK29 --- .../Actors/ScriptActor.cs | 34 +++- .../Scripts/ScriptRunLauncher.cs | 44 +++++ .../Actors/ScriptRunShedTests.cs | 151 ++++++++++++++++++ 3 files changed, 227 insertions(+), 2 deletions(-) diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs index d4f25ba3..c6e7db43 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs @@ -532,6 +532,17 @@ public class ScriptActor : ReceiveActor, IWithTimers _logger.LogDebug( "Script {Script} on {Instance}: skipping execution, min time between runs not elapsed ({Elapsed} < {Min})", _scriptName, _instanceName, elapsed, _minTimeBetweenRuns.Value); + // Arch-review F7: a TRACED run refused here is otherwise invisible to the Flow + // Debugger, which then blames a missing trigger. Leave a Failed ScriptRun row + // naming the guard instead. + if (trace) + { + ScriptRunLauncher.EmitSuppressedRun( + _serviceProvider, _logger, _scriptName, _instanceName, parentExecutionId, + $"suppressed: MinTimeBetweenRuns ({_minTimeBetweenRuns.Value}) not elapsed " + + $"since the previous run ({elapsed} ago).", + triggerExtra); + } return; } } @@ -574,7 +585,7 @@ public class ScriptActor : ReceiveActor, IWithTimers { if (callDepth == 0 && _runsInFlight >= _options.MaxConcurrentRunsPerScript) { - ShedRun(replyTo, correlationId); + ShedRun(replyTo, correlationId, parentExecutionId, trace, triggerExtra); return; } @@ -649,8 +660,18 @@ public class ScriptActor : ReceiveActor, IWithTimers /// an unrelated script's run) gets an explicit error so the caller fails fast rather than /// hanging to its Ask timeout. Nested (callDepth > 0) launches never reach here — /// see . + /// + /// Arch-review F7: a traced run shed here also leaves a Failed ScriptRun audit + /// row, so the Flow Debugger names the cap rather than reporting a missing trigger. The + /// trigger detail () rides along so the row still says which + /// attribute change would have fired the run. /// - private void ShedRun(IActorRef replyTo, string correlationId) + private void ShedRun( + IActorRef replyTo, + string correlationId, + Guid? parentExecutionId = null, + bool trace = false, + ScriptTraceExtra? triggerExtra = null) { _healthCollector?.IncrementScriptRunShed(); @@ -675,6 +696,15 @@ public class ScriptActor : ReceiveActor, IWithTimers correlationId, false, null, $"shed: {_runsInFlight} runs already in flight")); } + + if (trace) + { + ScriptRunLauncher.EmitSuppressedRun( + _serviceProvider, _logger, _scriptName, _instanceName, parentExecutionId, + $"shed: MaxConcurrentRunsPerScript reached — {_runsInFlight} runs already in " + + $"flight (cap {_options.MaxConcurrentRunsPerScript}).", + triggerExtra); + } } private void HandleExecutionCompleted(ScriptExecutionCompleted msg) diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs index 6a4564d6..111e85f8 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs @@ -515,6 +515,50 @@ internal static class ScriptRunLauncher } } + /// + /// Arch-review F7: a traced run that never launched (shed at the in-flight cap, or + /// suppressed by MinTimeBetweenRuns) still leaves a Failed + /// ScriptTrace.ScriptRun row, so the Flow Debugger explains the gap with the guard + /// that refused the run instead of reporting NO_TRIGGER_WITHIN_WINDOW — which reads + /// as "no value-change trigger on this attribute, or no device echo" and sends the operator + /// to check the wrong things. + /// + /// There is no collector: a shed run has no reply to ride on (an Ask caller gets the + /// shed ScriptCallResult from ScriptActor.ShedRun, not a trace list), so the + /// row goes to the audit writer only and reaches the debugger via PullTraceEvents / + /// Replay. The writer and identity providers come from a fresh scope because this runs on + /// the ACTOR thread, outside any launch scope. elapsedMs is 0 — the run never ran. + /// Best-effort and never throws: a no-op when there is no provider or no writer. + /// + internal static void EmitSuppressedRun( + IServiceProvider? serviceProvider, + ILogger logger, + string scriptName, + string instanceName, + Guid? parentExecutionId, + string reason, + ScriptTraceExtra? triggerExtra) + { + if (serviceProvider is null) return; + try + { + using var scope = serviceProvider.CreateScope(); + var writer = scope.ServiceProvider.GetService(); + if (writer is null) return; + var siteId = scope.ServiceProvider.GetService()?.SiteId ?? string.Empty; + var sourceNode = scope.ServiceProvider.GetService()?.NodeName; + + EmitScriptRun( + trace: true, collector: null, writer, logger, scriptName, instanceName, siteId, sourceNode, + executionId: Guid.NewGuid(), parentExecutionId, DateTime.UtcNow, elapsedMs: 0, + parameters: null, returnValue: null, error: reason, triggerExtra); + } + catch (Exception ex) + { + logger.LogWarning(ex, "Flow trace suppressed-run emission failed for {Script}", scriptName); + } + } + /// /// Flow Debugger (design 2026-09-05 §5.1): emits the ScriptTrace.ScriptRun row for a /// traced run — collector first (so the inline reply carries it), then the best-effort diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs index da2fb127..b6ea8915 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs @@ -3,14 +3,20 @@ using Akka.TestKit; using Akka.TestKit.Xunit2; using Microsoft.CodeAnalysis.CSharp.Scripting; using Microsoft.CodeAnalysis.Scripting; +using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging.Abstractions; +using ZB.MOM.WW.Audit; using ZB.MOM.WW.ScadaBridge.Commons.Messages.ScriptExecution; using ZB.MOM.WW.ScadaBridge.Commons.Messages.Streaming; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging; using ZB.MOM.WW.ScadaBridge.Commons.Types.Flattening; using ZB.MOM.WW.ScadaBridge.HealthMonitoring; +using ZB.MOM.WW.ScadaBridge.SiteEventLogging; using ZB.MOM.WW.ScadaBridge.SiteRuntime.Actors; using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; using ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.TestSupport; +using IAuditWriter = ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services.IAuditWriter; namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Actors; @@ -213,6 +219,151 @@ public class ScriptRunShedTests : TestKit, IDisposable Assert.Equal(4, alarm.UnderlyingActor.RunsInFlight); }, TimeSpan.FromSeconds(10)); } + + // --------------------------------------------------------------------------------------- + // Arch-review F7: a TRACED run refused by either guard (the in-flight cap, or + // MinTimeBetweenRuns) used to emit nothing at all, so the Flow Debugger reported + // NO_TRIGGER_WITHIN_WINDOW — "no value-change trigger on this attribute, or no device echo" + // — which is wrong in both cases and sends the operator to check the wrong things. Each + // guard now leaves a Failed ScriptTrace/ScriptRun row naming the guard that refused it. + // --------------------------------------------------------------------------------------- + + /// Audit writer fake: records every emitted row and can wait for one matching a predicate. + private sealed class CapturingAuditWriter : IAuditWriter + { + private readonly List _events = new(); + + public Task WriteAsync(AuditEvent evt, CancellationToken ct = default) + { + lock (_events) _events.Add(evt); + return Task.CompletedTask; + } + + public AuditEvent[] Snapshot() + { + lock (_events) return _events.ToArray(); + } + + public AuditEvent? WaitFor(Func predicate, TimeSpan timeout) + { + var deadline = DateTime.UtcNow + timeout; + while (DateTime.UtcNow < deadline) + { + lock (_events) + { + var hit = _events.FirstOrDefault(predicate); + if (hit is not null) return hit; + } + Thread.Sleep(25); + } + return null; + } + } + + private static IServiceProvider AuditServices(ISiteEventLogger siteLog, IAuditWriter writer) + { + var services = new ServiceCollection(); + services.AddSingleton(siteLog); + services.AddSingleton(writer); + return services.BuildServiceProvider(); + } + + private static ResolvedScript ValueChangeScript(string name, TimeSpan? minTimeBetweenRuns = null) => new() + { + CanonicalName = name, + TriggerType = "valuechange", + TriggerConfiguration = "{\"attribute\":\"Status\"}", + MinTimeBetweenRuns = minTimeBetweenRuns + }; + + private static bool IsFailedScriptRun(AuditEvent evt) => + evt.Action == "ScriptTrace.ScriptRun" && evt.AsRow().Status.ToString() == "Failed"; + + [Fact] + public void TracedRun_ShedAtTheCap_EmitsAFailedScriptRunRow_ParentedToTheWriter() + { + var siteLog = new FakeSiteEventLogger(); + var writer = new CapturingAuditWriter(); + var health = new SiteHealthCollector(); + var instance = CreateTestProbe().Ref; + var options = Options(); + + var actor = ActorOfAsTestActorRef( + Props.Create(() => new ScriptActor( + "Hot", "Inst1", instance, BlockingScript(), + ValueChangeScript("Hot"), + _sharedLibrary, options, NullLogger.Instance, + null, null, health, AuditServices(siteLog, writer), _scheduler, null)), + "shed-traced-" + Guid.NewGuid().ToString("N")); + + // Fill the cap with four untraced runs, all blocked in their bodies. + for (var i = 0; i < 4; i++) + actor.Tell(new ScriptCallRequest("Hot", null, 0, $"corr-{i}"), ActorRefs.NoSender); + + AwaitAssert(() => Assert.Equal(4, actor.UnderlyingActor.RunsInFlight), TimeSpan.FromSeconds(15)); + + // The fifth trigger is a TRACED value change stamped by its writing execution. + var parent = Guid.NewGuid(); + actor.Tell(new AttributeValueChanged( + "Inst1", "Status", "Status", "Running", "Good", DateTimeOffset.UtcNow, + SourceExecutionId: parent, Trace: true)); + + var evt = writer.WaitFor(IsFailedScriptRun, TimeSpan.FromSeconds(10)); + Assert.NotNull(evt); + var row = evt!.AsRow(); + Assert.Equal(parent, row.ParentExecutionId); + Assert.NotNull(row.ExecutionId); + Assert.StartsWith("shed: MaxConcurrentRunsPerScript", row.ErrorMessage); + Assert.Equal("Hot", evt.Target); + Assert.Equal("Inst1", row.SourceInstanceId); + // The trigger detail survives, so the debugger can still name the attribute. + var extra = ScriptTraceExtra.TryParse(row.Extra)!; + Assert.Equal("valuechange", extra.TriggerKind); + Assert.Equal("Status", extra.TriggerAttribute); + + // Still exactly four in flight — the shed run was never launched. + Assert.Equal(4, actor.UnderlyingActor.RunsInFlight); + } + + [Fact] + public void TracedRun_SuppressedByMinTimeBetweenRuns_EmitsAFailedScriptRunRow() + { + var siteLog = new FakeSiteEventLogger(); + var writer = new CapturingAuditWriter(); + var health = new SiteHealthCollector(); + var instance = CreateTestProbe().Ref; + var options = Options(); + + var actor = ActorOfAsTestActorRef( + Props.Create(() => new ScriptActor( + "Throttled", "Inst1", instance, CompileRaw("return null;"), + ValueChangeScript("Throttled", TimeSpan.FromMinutes(10)), + _sharedLibrary, options, NullLogger.Instance, + null, null, health, AuditServices(siteLog, writer), _scheduler, null)), + "throttled-traced-" + Guid.NewGuid().ToString("N")); + + // First traced change runs (and emits a Delivered row); the second, back to back, + // is inside MinTimeBetweenRuns and never launches. + var parent = Guid.NewGuid(); + for (var i = 0; i < 2; i++) + { + actor.Tell(new AttributeValueChanged( + "Inst1", "Status", "Status", $"Run{i}", "Good", DateTimeOffset.UtcNow, + SourceExecutionId: parent, Trace: true)); + } + + var evt = writer.WaitFor(IsFailedScriptRun, TimeSpan.FromSeconds(10)); + Assert.NotNull(evt); + var row = evt!.AsRow(); + Assert.Equal(parent, row.ParentExecutionId); + Assert.StartsWith("suppressed: MinTimeBetweenRuns", row.ErrorMessage); + + // The first run still produced its ordinary Delivered row — the guard row is additive. + AwaitAssert(() => Assert.Contains( + writer.Snapshot(), + e => e.Action == "ScriptTrace.ScriptRun" && e.AsRow().Status.ToString() == "Delivered"), + TimeSpan.FromSeconds(10)); + } } /// Test hook used to hold script runs in flight while the cap is exercised.