Merge branch 'worktree-agent-a6faa2ddb571f8394' into fix/flow-debugger-arch-review
This commit is contained in:
@@ -532,6 +532,17 @@ public class ScriptActor : ReceiveActor, IWithTimers
|
|||||||
_logger.LogDebug(
|
_logger.LogDebug(
|
||||||
"Script {Script} on {Instance}: skipping execution, min time between runs not elapsed ({Elapsed} < {Min})",
|
"Script {Script} on {Instance}: skipping execution, min time between runs not elapsed ({Elapsed} < {Min})",
|
||||||
_scriptName, _instanceName, elapsed, _minTimeBetweenRuns.Value);
|
_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;
|
return;
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
@@ -574,7 +585,7 @@ public class ScriptActor : ReceiveActor, IWithTimers
|
|||||||
{
|
{
|
||||||
if (callDepth == 0 && _runsInFlight >= _options.MaxConcurrentRunsPerScript)
|
if (callDepth == 0 && _runsInFlight >= _options.MaxConcurrentRunsPerScript)
|
||||||
{
|
{
|
||||||
ShedRun(replyTo, correlationId);
|
ShedRun(replyTo, correlationId, parentExecutionId, trace, triggerExtra);
|
||||||
return;
|
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
|
/// an unrelated script's run) gets an explicit error so the caller fails fast rather than
|
||||||
/// hanging to its Ask timeout. Nested (<c>callDepth > 0</c>) launches never reach here —
|
/// hanging to its Ask timeout. Nested (<c>callDepth > 0</c>) launches never reach here —
|
||||||
/// see <see cref="SpawnExecution"/>.
|
/// 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>
|
/// </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();
|
_healthCollector?.IncrementScriptRunShed();
|
||||||
|
|
||||||
@@ -675,6 +696,15 @@ public class ScriptActor : ReceiveActor, IWithTimers
|
|||||||
correlationId, false, null,
|
correlationId, false, null,
|
||||||
$"shed: {_runsInFlight} runs already in flight"));
|
$"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)
|
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>
|
/// <summary>
|
||||||
/// Flow Debugger (design 2026-09-05 §5.1): emits the <c>ScriptTrace.ScriptRun</c> row for a
|
/// 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
|
/// 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 Akka.TestKit.Xunit2;
|
||||||
using Microsoft.CodeAnalysis.CSharp.Scripting;
|
using Microsoft.CodeAnalysis.CSharp.Scripting;
|
||||||
using Microsoft.CodeAnalysis.Scripting;
|
using Microsoft.CodeAnalysis.Scripting;
|
||||||
|
using Microsoft.Extensions.DependencyInjection;
|
||||||
using Microsoft.Extensions.Logging.Abstractions;
|
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.ScriptExecution;
|
||||||
using ZB.MOM.WW.ScadaBridge.Commons.Messages.Streaming;
|
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.Commons.Types.Flattening;
|
||||||
using ZB.MOM.WW.ScadaBridge.HealthMonitoring;
|
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.Actors;
|
||||||
using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
|
using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
|
||||||
using ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.TestSupport;
|
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;
|
namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Actors;
|
||||||
|
|
||||||
@@ -213,6 +219,151 @@ public class ScriptRunShedTests : TestKit, IDisposable
|
|||||||
Assert.Equal(4, alarm.UnderlyingActor.RunsInFlight);
|
Assert.Equal(4, alarm.UnderlyingActor.RunsInFlight);
|
||||||
}, TimeSpan.FromSeconds(10));
|
}, 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>
|
/// <summary>Test hook used to hold script runs in flight while the cap is exercised.</summary>
|
||||||
|
|||||||
Reference in New Issue
Block a user