From a4e8518e690350437b2bb98966387c1a5ee7ac0d Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 8 Sep 2026 01:27:44 -0400 Subject: [PATCH] =?UTF-8?q?fix(management):=20FlowDebugRunner.RunScriptAsy?= =?UTF-8?q?nc=20=E2=80=94=20always=20write=20the=20root=20row=20after=20a?= =?UTF-8?q?=20routed=20call;=20timeout=20+=20unserializable-return=20tests?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Claude-Session: https://claude.ai/code/session_01NcMG6xXdsJbmD2wYAgkK29 --- .../FlowDebug/FlowDebugRunner.cs | 63 ++++++++++++++-- .../FlowDebugRunnerTests.cs | 73 ++++++++++++++++++- 2 files changed, 127 insertions(+), 9 deletions(-) diff --git a/src/ZB.MOM.WW.ScadaBridge.ManagementService/FlowDebug/FlowDebugRunner.cs b/src/ZB.MOM.WW.ScadaBridge.ManagementService/FlowDebug/FlowDebugRunner.cs index 5473b842..a79f0936 100644 --- a/src/ZB.MOM.WW.ScadaBridge.ManagementService/FlowDebug/FlowDebugRunner.cs +++ b/src/ZB.MOM.WW.ScadaBridge.ManagementService/FlowDebug/FlowDebugRunner.cs @@ -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); } + /// + /// The timed-out message shared by both Live entry points, so the two paths never drift. + /// + private static string TimeoutMessage(TimeSpan timeout) => + $"Flow Debugger run timed out after {timeout.TotalSeconds}s + {RunGrace.TotalSeconds}s grace"; + + /// + /// Serializes a routed call's return value for the root row's ResponseSummary, NEVER + /// throwing: rejects named floating-point literals, + /// so a script returning double.NaN / 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. + /// + /// + /// The catch is deliberately broad (as 's already is): the value + /// crossing this seam came from a user-authored script, and the serializer's failure mode varies + /// by value — ArgumentException for a non-finite number, for a + /// cycle, for an unmappable type. A best-effort audit summary + /// must not be the thing that fails a call the site already ran. + /// + /// + private static string? SerializeReturnValue(object? returnValue) + { + if (returnValue is null) return null; + try + { + return JsonSerializer.Serialize(returnValue, ScriptTraceExtra.JsonOptions); + } + catch (Exception ex) + { + return $""; + } + } + private static void EnsureActiveNode(IServiceProvider sp) { var gate = sp.GetService(); diff --git a/tests/ZB.MOM.WW.ScadaBridge.ManagementService.Tests/FlowDebugRunnerTests.cs b/tests/ZB.MOM.WW.ScadaBridge.ManagementService.Tests/FlowDebugRunnerTests.cs index 1afa25de..acc3b345 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.ManagementService.Tests/FlowDebugRunnerTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.ManagementService.Tests/FlowDebugRunnerTests.cs @@ -489,10 +489,20 @@ public class FlowDebugRunnerTests RouteToSetAttributesRequest? write = null; _router.RouteToSetAttributesAsync("site-a", Arg.Do(r => write = r), Arg.Any()) .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>(), Arg.Any(), Arg.Any(), Arg.Any()) - .Returns(ci => (IReadOnlyList)[ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.ScriptRun, AuditStatus.Delivered, - eventId: Guid.Parse("bbbbbbbb-0000-0000-0000-000000000001"), - executionId: Guid.NewGuid(), parentExecutionId: ((IReadOnlyCollection)ci[1]).First(), target: "OnLevel")]); + .Returns(ci => + { + calls++; + return calls >= 2 + ? (IReadOnlyList)[ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.ScriptRun, AuditStatus.Delivered, + eventId: Guid.Parse("bbbbbbbb-0000-0000-0000-000000000001"), + executionId: Guid.NewGuid(), parentExecutionId: ((IReadOnlyCollection)ci[1]).First(), target: "OnLevel")] + : Array.Empty(); + }); 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(), Arg.Any()) + .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); + } + + /// A routed call that never answers until its token is cancelled — the timeout path. + private static async Task 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(), Arg.Any()) + .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() {