fix(management): FlowDebugRunner.RunScriptAsync — always write the root row after a routed call; timeout + unserializable-return tests

Claude-Session: https://claude.ai/code/session_01NcMG6xXdsJbmD2wYAgkK29
This commit is contained in:
Joseph Doherty
2026-09-08 01:27:44 -04:00
parent 11d32335af
commit a4e8518e69
2 changed files with 127 additions and 9 deletions
@@ -158,8 +158,7 @@ public sealed class FlowDebugRunner
}
catch (OperationCanceledException) when (!ct.IsCancellationRequested)
{
result = new InboundScriptResult(false, null,
$"Flow Debugger run timed out after {timeout.TotalSeconds}s + {RunGrace.TotalSeconds}s grace", TimeoutCode);
result = new InboundScriptResult(false, null, TimeoutMessage(timeout), TimeoutCode);
}
}
@@ -316,13 +315,31 @@ public sealed class FlowDebugRunner
catch (OperationCanceledException) when (!ct.IsCancellationRequested)
{
timedOut = true;
response = new RouteToCallResponse(request.CorrelationId, false, null,
$"Flow Debugger run timed out after {timeout.TotalSeconds}s + {RunGrace.TotalSeconds}s grace", DateTimeOffset.UtcNow);
response = new RouteToCallResponse(
request.CorrelationId, false, null, TimeoutMessage(timeout), DateTimeOffset.UtcNow);
}
}
// Everything from here to WriteCentralAsync runs AFTER the site already executed the
// script — a real side effect. Nothing in this stretch may throw, or the root row is never
// written and the operator sees ManagementActor.MapFault's generic "internal error" for a
// call that actually succeeded. So the trace drain skips a faulting event and the return
// value falls back to a placeholder, the same way InboundScriptExecutor turns a script's
// own faults into a captured error rather than an escaping exception.
foreach (var e in response.TraceEvents ?? [])
collector.Add(e);
{
try
{
collector.Add(e);
}
catch (Exception ex)
{
_logger.LogWarning(ex,
"Flow Debugger dropped an inline trace event from the run of {Script} on {Instance}",
script.CanonicalName, instance.UniqueName);
}
}
var events = collector.Complete();
var rootRow = ScadaBridgeAuditEventFactory.Create(
@@ -338,7 +355,7 @@ public sealed class FlowDebugRunner
durationMs: (int)Math.Min(sw.ElapsedMilliseconds, int.MaxValue),
errorMessage: response.ErrorMessage,
requestSummary: cmd.Parameters is { } p ? p.GetRawText() : null,
responseSummary: response.ReturnValue is null ? null : JsonSerializer.Serialize(response.ReturnValue, ScriptTraceExtra.JsonOptions),
responseSummary: SerializeReturnValue(response.ReturnValue),
extra: new ScriptTraceExtra { Source = SourceTag, ChildExecutionId = response.ChildExecutionId }.ToJson());
await WriteCentralAsync(sp, rootRow, ct).ConfigureAwait(false);
@@ -477,6 +494,40 @@ public sealed class FlowDebugRunner
return new FlowDebugRunResult(rootId, true, null, null, events, false, startedAt, DateTimeOffset.UtcNow);
}
/// <summary>
/// The timed-out message shared by both Live entry points, so the two paths never drift.
/// </summary>
private static string TimeoutMessage(TimeSpan timeout) =>
$"Flow Debugger run timed out after {timeout.TotalSeconds}s + {RunGrace.TotalSeconds}s grace";
/// <summary>
/// Serializes a routed call's return value for the root row's <c>ResponseSummary</c>, NEVER
/// throwing: <see cref="ScriptTraceExtra.JsonOptions"/> rejects named floating-point literals,
/// so a script returning <c>double.NaN</c> / an infinity — or any other value the serializer
/// cannot represent — would otherwise take down the audit write of a call that already ran.
/// The placeholder keeps the row (and the operator's Live result) intact.
///
/// <para>
/// The catch is deliberately broad (as <see cref="WriteCentralAsync"/>'s already is): the value
/// crossing this seam came from a user-authored script, and the serializer's failure mode varies
/// by value — <c>ArgumentException</c> for a non-finite number, <see cref="JsonException"/> for a
/// cycle, <see cref="NotSupportedException"/> for an unmappable type. A best-effort audit summary
/// must not be the thing that fails a call the site already ran.
/// </para>
/// </summary>
private static string? SerializeReturnValue(object? returnValue)
{
if (returnValue is null) return null;
try
{
return JsonSerializer.Serialize(returnValue, ScriptTraceExtra.JsonOptions);
}
catch (Exception ex)
{
return $"<unserializable return value: {ex.GetType().Name}>";
}
}
private static void EnsureActiveNode(IServiceProvider sp)
{
var gate = sp.GetService<IActiveNodeGate>();
@@ -489,10 +489,20 @@ public class FlowDebugRunnerTests
RouteToSetAttributesRequest? write = null;
_router.RouteToSetAttributesAsync("site-a", Arg.Do<RouteToSetAttributesRequest>(r => write = r), Arg.Any<CancellationToken>())
.Returns(ci => new RouteToSetAttributesResponse(((RouteToSetAttributesRequest)ci[1]).CorrelationId, true, null, DateTimeOffset.UtcNow));
// Mirrors RunValueChange_TracedWrite_ThenPollsUntilSpawnedRunSettles: nothing on the first
// poll, then the SAME row (fixed event id) from the second on — a fresh id per poll would
// re-arm the settle window forever and the loop would only ever end on the deadline.
var calls = 0;
puller.PullAsync("site-a", Arg.Any<IReadOnlyCollection<Guid>>(), Arg.Any<DateTime>(), Arg.Any<int>(), Arg.Any<CancellationToken>())
.Returns(ci => (IReadOnlyList<AuditEvent>)[ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.ScriptRun, AuditStatus.Delivered,
eventId: Guid.Parse("bbbbbbbb-0000-0000-0000-000000000001"),
executionId: Guid.NewGuid(), parentExecutionId: ((IReadOnlyCollection<Guid>)ci[1]).First(), target: "OnLevel")]);
.Returns(ci =>
{
calls++;
return calls >= 2
? (IReadOnlyList<AuditEvent>)[ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.ScriptRun, AuditStatus.Delivered,
eventId: Guid.Parse("bbbbbbbb-0000-0000-0000-000000000001"),
executionId: Guid.NewGuid(), parentExecutionId: ((IReadOnlyCollection<Guid>)ci[1]).First(), target: "OnLevel")]
: Array.Empty<AuditEvent>();
});
var result = await Runner().RunScriptAsync(_services.BuildServiceProvider(),
new FlowDebugRunScriptCommand(5, "onlevel", null, "7", WaitSeconds: 10), Deployer, CancellationToken.None);
@@ -500,7 +510,12 @@ public class FlowDebugRunnerTests
Assert.True(result.Completed, result.Error);
Assert.Equal("7", write!.AttributeValues["Level"]);
Assert.True(write.Trace);
Assert.Equal(result.RootExecutionId, write.ParentExecutionId);
Assert.Equal(2, result.Events.Count);
Assert.Equal(AuditKind.AttributeWrite, result.Events[0].AsRow().Kind);
Assert.Equal(AuditKind.ScriptRun, result.Events[1].AsRow().Kind);
// Settled: at least one quiet poll (2 s window) after the last new row, then stopped.
Assert.True(calls >= 3, $"expected settle polls, got {calls}");
await _router.DidNotReceiveWithAnyArgs().RouteToCallAsync(default!, default!, default);
}
@@ -599,6 +614,58 @@ public class FlowDebugRunnerTests
await pipeline.DidNotReceiveWithAnyArgs().FlattenAndValidateAsync(default, default, default, default);
}
[Fact]
public async Task RunScript_CallKind_UnserializableReturnValue_StillWritesTheRootRow()
{
// The site already RAN the script by the time the root row is built, so a return value the
// serializer refuses (ScriptTraceExtra.JsonOptions rejects named floating-point literals)
// must not lose the audit row and surface as MapFault's generic "internal error".
WireScript(CallScript("Manual"));
_router.RouteToCallAsync("site-a", Arg.Any<RouteToCallRequest>(), Arg.Any<CancellationToken>())
.Returns(ci => new RouteToCallResponse(((RouteToCallRequest)ci[1]).CorrelationId, true, double.NaN, null, DateTimeOffset.UtcNow));
var result = await Runner().RunScriptAsync(_services.BuildServiceProvider(),
new FlowDebugRunScriptCommand(5, "Manual", null, null), Deployer, CancellationToken.None);
Assert.True(result.Completed, result.Error);
Assert.Null(result.ErrorCode);
var root = Assert.Single(result.Events).AsRow();
Assert.Equal(AuditKind.RouteCall, root.Kind);
Assert.Contains("unserializable", root.ResponseSummary);
var written = Assert.Single(_central);
Assert.Equal(AuditKind.RouteCall, written.AsRow().Kind);
}
/// <summary>A routed call that never answers until its token is cancelled — the timeout path.</summary>
private static async Task<RouteToCallResponse> NeverAnswersAsync(CancellationToken ct)
{
await Task.Delay(Timeout.Infinite, ct);
throw new InvalidOperationException("unreachable");
}
[Fact]
public async Task RunScript_CallKind_Timeout_ReportsTimeoutCode()
{
// NOTE: this test really waits ExecutionTimeoutSeconds (1 s) + RunGrace (10 s) — the runner
// arms a real CancelAfter, which the injectable delay/clock does not drive. ~11 s is the
// price of the only coverage of this path.
WireScript(CallScript("Manual", timeout: 1));
_router.RouteToCallAsync("site-a", Arg.Any<RouteToCallRequest>(), Arg.Any<CancellationToken>())
.Returns(ci => NeverAnswersAsync((CancellationToken)ci[2]));
var result = await Runner().RunScriptAsync(_services.BuildServiceProvider(),
new FlowDebugRunScriptCommand(5, "Manual", null, null), Deployer, CancellationToken.None);
Assert.False(result.Completed);
Assert.Equal(FlowDebugRunner.TimeoutCode, result.ErrorCode);
Assert.Contains("timed out", result.Error);
var root = Assert.Single(result.Events).AsRow();
Assert.Equal(AuditKind.RouteCall, root.Kind);
Assert.Equal(AuditStatus.Failed, root.Status);
var written = Assert.Single(_central);
Assert.Equal(AuditStatus.Failed, written.AsRow().Status);
}
[Fact]
public async Task RunScript_CallKind_RootRow_IsRedacted_WhenARedactorIsRegistered()
{