fix(site-runtime): shed or rate-limited traced runs emit a Failed ScriptRun row (arch-review F7)

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
2026-09-06 14:22:11 -04:00
parent 05b97b596d
commit 105541b655
3 changed files with 227 additions and 2 deletions
@@ -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 (<c>callDepth &gt; 0</c>) launches never reach here —
    /// see <see cref="SpawnExecution"/>.
+    ///
+    /// <para>Arch-review F7: a traced run shed here also leaves a Failed <c>ScriptRun</c> audit
+    /// row, so the Flow Debugger names the cap rather than reporting a missing trigger. The
+    /// trigger detail (<paramref name="triggerExtra"/>) rides along so the row still says which
+    /// attribute change would have fired the run.</para>
    /// </summary>
-    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)
@@ -515,6 +515,50 @@ internal static class ScriptRunLauncher
        }
    }

+    /// <summary>
+    /// Arch-review F7: a traced run that never launched (shed at the in-flight cap, or
+    /// suppressed by <c>MinTimeBetweenRuns</c>) still leaves a <c>Failed</c>
+    /// <c>ScriptTrace.ScriptRun</c> row, so the Flow Debugger explains the gap with the guard
+    /// that refused the run instead of reporting <c>NO_TRIGGER_WITHIN_WINDOW</c> — which reads
+    /// as "no value-change trigger on this attribute, or no device echo" and sends the operator
+    /// to check the wrong things.
+    ///
+    /// <para>There is no collector: a shed run has no reply to ride on (an Ask caller gets the
+    /// shed <c>ScriptCallResult</c> from <c>ScriptActor.ShedRun</c>, not a trace list), so the
+    /// row goes to the audit writer only and reaches the debugger via <c>PullTraceEvents</c> /
+    /// Replay. The writer and identity providers come from a fresh scope because this runs on
+    /// the ACTOR thread, outside any launch scope. <c>elapsedMs</c> is 0 — the run never ran.
+    /// Best-effort and never throws: a no-op when there is no provider or no writer.</para>
+    /// </summary>
+    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<IAuditWriter>();
+            if (writer is null) return;
+            var siteId = scope.ServiceProvider.GetService<ISiteIdentityProvider>()?.SiteId ?? string.Empty;
+            var sourceNode = scope.ServiceProvider.GetService<INodeIdentityProvider>()?.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);
+        }
+    }
+
    /// <summary>
    /// Flow Debugger (design 2026-09-05 §5.1): emits the <c>ScriptTrace.ScriptRun</c> row for a
    /// traced run — collector first (so the inline reply carries it), then the best-effort
@@ -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.
+    // ---------------------------------------------------------------------------------------
+
+    /// <summary>Audit writer fake: records every emitted row and can wait for one matching a predicate.</summary>
+    private sealed class CapturingAuditWriter : IAuditWriter
+    {
+        private readonly List<AuditEvent> _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<AuditEvent, bool> 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<ScriptActor>(
+            Props.Create(() => new ScriptActor(
+                "Hot", "Inst1", instance, BlockingScript(),
+                ValueChangeScript("Hot"),
+                _sharedLibrary, options, NullLogger<ScriptActor>.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<ScriptActor>(
+            Props.Create(() => new ScriptActor(
+                "Throttled", "Inst1", instance, CompileRaw("return null;"),
+                ValueChangeScript("Throttled", TimeSpan.FromMinutes(10)),
+                _sharedLibrary, options, NullLogger<ScriptActor>.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));
+    }
 }

 /// <summary>Test hook used to hold script runs in flight while the cap is exercised.</summary>