From 750c542c2f495ff8b0332e0f9413921660319e8e Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 9 Sep 2026 12:23:01 -0400 Subject: [PATCH] feat(site-runtime): ScriptRun rows carry exception detail; per-run log line cap + closing row (D3/D7) --- .../Scripts/ScriptRunLauncher.cs | 38 ++++- .../SiteRuntimeOptions.cs | 14 ++ .../SiteRuntimeOptionsValidator.cs | 6 + .../Scripts/ScriptRunLauncherTraceTests.cs | 159 ++++++++++++++++++ .../SiteRuntimeOptionsValidatorTests.cs | 12 ++ 5 files changed, 223 insertions(+), 6 deletions(-) create mode 100644 tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunLauncherTraceTests.cs diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs index 4a86409f..2fc29b44 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs @@ -400,7 +400,12 @@ internal static class ScriptRunLauncher scriptTimeoutToken: cts.Token, // Flow Debugger (design §5.2/§5.4): the trace flag and the inline sink. isTraced: trace, - traceCollector: collector); + traceCollector: collector, + // Step logs (design 2026-09-09 D7): the per-run ScriptLog row cap. Read off + // effectiveOptions (the IOptionsMonitor snapshot taken at the top of this run), + // so an operator's live edit applies from the NEXT run, like the event-policy + // flags above. + maxLogLinesPerRun: effectiveOptions.MaxLogLinesPerRun); var globals = new ScriptGlobals { @@ -426,13 +431,17 @@ internal static class ScriptRunLauncher var state = await compiledScript.RunAsync(globals, cts.Token); + // Step logs (design D7): close the run's log BEFORE the anchor row, so the closing + // "N line(s) dropped" row precedes the ScriptRun in emission order on every path. + context.Log.FlushDropped(); + // Flow Debugger: the ScriptRun row goes into the collector BEFORE the reply so the // inline list the caller receives includes the run itself. Complete() (not Snapshot) // closes the sink at the same instant — outbound rows finishing after this point // (plan 2026-09-06 D5) go to the audit writer only. EmitScriptRun(trace, collector, auditWriter, logger, scriptName, instanceName, siteId, sourceNode, context.ExecutionId, parentExecutionId, startedUtc, runStopwatch.ElapsedMilliseconds, - parameters, state.ReturnValue, error: null, triggerExtra); + parameters, state.ReturnValue, error: null, errorDetail: null, triggerExtra); // Send result to requester if this was an Ask-based call if (!replyTo.IsNobody()) @@ -467,9 +476,14 @@ internal static class ScriptRunLauncher _ = siteEventLogger?.LogEventAsync( "script", "Error", instanceName, $"ScriptActor:{scriptName}", errorMsg); + // Step logs (design D7): see the success path — the closing row comes first. + context?.Log.FlushDropped(); + + // A timeout carries NO errorDetail (design D3): the OperationCanceledException's stack + // is the launcher's cancellation plumbing, not the script's, so it would mislead. EmitScriptRun(trace, collector, auditWriter, logger, scriptName, instanceName, siteId, sourceNode, context?.ExecutionId, parentExecutionId, startedUtc, runStopwatch.ElapsedMilliseconds, - parameters, null, errorMsg, triggerExtra); + parameters, null, errorMsg, errorDetail: null, triggerExtra); if (!replyTo.IsNobody()) { @@ -492,9 +506,14 @@ internal static class ScriptRunLauncher _ = siteEventLogger?.LogEventAsync( "script", "Error", instanceName, $"ScriptActor:{scriptName}", errorMsg, ex.ToString()); + // Step logs (design D7): see the success path — the closing row comes first. + context?.Log.FlushDropped(); + + // Design D3: the failing run's full exception — type, message and stack — so the Flow + // Debugger's red node can show the stack, not just the one-line message. EmitScriptRun(trace, collector, auditWriter, logger, scriptName, instanceName, siteId, sourceNode, context?.ExecutionId, parentExecutionId, startedUtc, runStopwatch.ElapsedMilliseconds, - parameters, null, errorMsg, triggerExtra); + parameters, null, errorMsg, errorDetail: ex.ToString(), triggerExtra); if (!replyTo.IsNobody()) { @@ -551,7 +570,7 @@ internal static class ScriptRunLauncher 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); + parameters: null, returnValue: null, error: reason, errorDetail: null, triggerExtra); } catch (Exception ex) { @@ -564,13 +583,19 @@ internal static class ScriptRunLauncher /// traced run — collector first (so the inline reply carries it), then the best-effort /// audit writer. OccurredAtUtc is the run's START so the row sorts before the /// writes/waits the run made. No-op when untraced; never throws. + /// + /// Step logs (design 2026-09-09 D3): carries the failing + /// run's full Exception.ToString() — type, message and stack — so the Flow Debugger can + /// show the stack behind a red node instead of only the one-line message. A TIMED-OUT run + /// passes null on purpose: its OperationCanceledException stack is the launcher's own + /// cancellation plumbing, not the script's, and would mislead. /// private static void EmitScriptRun( bool trace, FlowTraceCollector? collector, IAuditWriter? auditWriter, ILogger logger, string scriptName, string instanceName, string siteId, string? sourceNode, Guid? executionId, Guid? parentExecutionId, DateTime startedUtc, long elapsedMs, IReadOnlyDictionary? parameters, object? returnValue, string? error, - ScriptTraceExtra? triggerExtra) + string? errorDetail, ScriptTraceExtra? triggerExtra) { if (!trace) return; try @@ -586,6 +611,7 @@ internal static class ScriptRunLauncher sourceInstanceId: instanceName, sourceScript: sourceScript, durationMs: (int)Math.Min(elapsedMs, int.MaxValue), errorMessage: error, + errorDetail: errorDetail, requestSummary: TraceJson(parameters), responseSummary: TraceJson(returnValue), extra: (triggerExtra ?? new ScriptTraceExtra { TriggerKind = "call" }).ToJson()); diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptions.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptions.cs index c5ec6952..5b1dd7c8 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptions.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptions.cs @@ -243,4 +243,18 @@ public class SiteRuntimeOptions /// Default: 30. /// public int TraceArmWindowSeconds { get; set; } = 30; + + /// + /// Flow Debugger step logs (design 2026-09-09 D7): the maximum number of ScriptLog + /// trace rows ONE script run may produce — the author's own Log.* lines plus the + /// runtime lines captured while the run is traced. Lines past the cap are counted and + /// dropped, and the run emits one closing warn row naming the dropped count, so a + /// chatty script degrades to a truncated log instead of an unbounded row stream. + /// + /// The cap is per RUN, not per script: an inline shared script shares its caller's + /// logger and therefore its counter. It only bounds trace rows — every line still reaches + /// the node's ILogger, traced or not — and an untraced run produces no rows at all. + /// Must be greater than 0. Default: 200. + /// + public int MaxLogLinesPerRun { get; set; } = 200; } diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptionsValidator.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptionsValidator.cs index d77a3fd3..98c916aa 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptionsValidator.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptionsValidator.cs @@ -113,5 +113,11 @@ public sealed class SiteRuntimeOptionsValidator : OptionsValidatorBase 0, + $"ScadaBridge:SiteRuntime:MaxLogLinesPerRun must be greater than 0 " + + $"(was {options.MaxLogLinesPerRun}); it is the per-run cap on Flow Debugger ScriptLog " + + "rows a script's Log.* calls may produce (design 2026-09-09 D7), and a run that may " + + "emit no lines at all cannot report its own truncation."); } } diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunLauncherTraceTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunLauncherTraceTests.cs new file mode 100644 index 00000000..bf96916e --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunLauncherTraceTests.cs @@ -0,0 +1,159 @@ +using Akka.Actor; +using Akka.TestKit.Xunit2; +using Microsoft.CodeAnalysis.CSharp.Scripting; +using Microsoft.CodeAnalysis.Scripting; +using Microsoft.Extensions.Logging.Abstractions; +using ZB.MOM.WW.Audit; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.ScriptExecution; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Scripts; +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts; + +/// +/// Flow Debugger step logs (design 2026-09-09 D3/D7) at the launcher boundary: the +/// ScriptRun anchor row a traced run returns inline carries the failing run's full +/// exception detail (and deliberately none for a timeout), and the run's log lines are bounded +/// by SiteRuntimeOptions.MaxLogLinesPerRun with one closing row naming the drops — all +/// of it emitted BEFORE the anchor, so the Flow Debugger reads a run's lines in order. +/// +public class ScriptRunLauncherTraceTests : TestKit, IDisposable +{ + /// Own pool per class (#18 seam), so a wedged body cannot strand the process-wide one. + private readonly ScriptExecutionScheduler _scheduler = new(4); + private readonly SharedScriptLibrary _sharedLibrary; + + public ScriptRunLauncherTraceTests() + => _sharedLibrary = new SharedScriptLibrary( + new ScriptCompilationService(NullLogger.Instance), + NullLogger.Instance); + + void IDisposable.Dispose() + { + Shutdown(); + _scheduler.Dispose(); + } + + // ── helpers ────────────────────────────────────────────────────────────────── + + private static Script CompileScript(string code) + { + var scriptOptions = ScriptOptions.Default + .WithReferences(typeof(object).Assembly, typeof(Enumerable).Assembly, + typeof(ScriptGlobals).Assembly) + .WithImports("System", "System.Collections.Generic", "System.Linq", "System.Threading.Tasks"); + var script = CSharpScript.Create(code, scriptOptions, typeof(ScriptGlobals)); + script.Compile(); + return script; + } + + private static AuditRowProjection.AuditRowValues Row(AuditEvent evt) => evt.AsRow(); + + private static ScriptTraceExtra Extra(AuditEvent evt) => ScriptTraceExtra.TryParse(Row(evt).Extra)!; + + /// Runs one traced script to completion and returns the reply's inline trace rows. + private ScriptCallResult RunTraced(string body, SiteRuntimeOptions options) + { + var caller = CreateTestProbe(); + ScriptRunLauncher.LaunchScript( + scriptName: "Runner", + instanceName: "Inst1", + compiledScript: CompileScript(body), + parameters: null, + callDepth: 0, + instanceActor: CreateTestProbe().Ref, + sharedScriptLibrary: _sharedLibrary, + options: options, + replyTo: caller.Ref, + correlationId: "corr-1", + completionTarget: CreateTestProbe().Ref, + siteCommunicationActor: null, + logger: NullLogger.Instance, + scope: ScriptScope.Root, + runId: 1, + healthCollector: null, + serviceProvider: null, + parentExecutionId: null, + executionTimeoutSeconds: null, + scheduler: _scheduler, + trace: true, + triggerExtra: null); + + return caller.ExpectMsg(TimeSpan.FromSeconds(20)); + } + + private static SiteRuntimeOptions Options(int timeoutSeconds = 30, int maxLogLines = 200) => new() + { + MaxScriptCallDepth = 10, + ScriptExecutionTimeoutSeconds = timeoutSeconds, + StuckScriptGraceMs = 30000, + MaxLogLinesPerRun = maxLogLines, + }; + + private static AuditEvent ScriptRunRow(ScriptCallResult result) + => Assert.Single(result.TraceEvents!, e => Row(e).Kind == AuditKind.ScriptRun); + + // ── (a) a throwing run carries the exception's full detail ─────────────────── + + [Fact] + public void ThrowingTracedRun_ScriptRunRow_CarriesTheFullExceptionDetail() + { + var result = RunTraced("throw new InvalidOperationException(\"boom\");", Options()); + + Assert.False(result.Success); + var row = Row(ScriptRunRow(result)); + Assert.Equal(AuditStatus.Failed, row.Status); + Assert.Contains("boom", row.ErrorMessage); + Assert.NotNull(row.ErrorDetail); + // Type name first, then the stack — the whole point of D3 over the one-line message. + Assert.StartsWith("System.InvalidOperationException", row.ErrorDetail); + Assert.Contains(" at ", row.ErrorDetail); + } + + // ── (b) a timeout carries NO detail (the stack would be the launcher's) ────── + + [Fact] + public void TimedOutTracedRun_ScriptRunRow_CarriesNoExceptionDetail() + { + var result = RunTraced( + "while (true) { await Task.Delay(25, CancellationToken); }", + Options(timeoutSeconds: 1)); + + Assert.False(result.Success); + var row = Row(ScriptRunRow(result)); + Assert.Equal(AuditStatus.Failed, row.Status); + Assert.Contains("timed out", row.ErrorMessage); + Assert.Null(row.ErrorDetail); + } + + // ── (c) the per-run line cap, its closing row, and emission order ──────────── + + [Fact] + public void TracedRun_CapsLogLines_AndEmitsTheClosingRowBeforeTheAnchor() + { + var result = RunTraced( + "Log.Info(\"a\"); Log.Info(\"b\"); Log.Info(\"c\"); Log.Info(\"d\"); Log.Info(\"e\"); return null;", + Options(maxLogLines: 2)); + + Assert.True(result.Success); + var rows = result.TraceEvents!; + + var logs = rows.Where(e => Row(e).Kind == AuditKind.ScriptLog).ToList(); + var scriptLines = logs.Where(e => Extra(e).LogSource == "script").ToList(); + Assert.Equal(2, scriptLines.Count); + Assert.Equal(["a", "b"], scriptLines.Select(e => Row(e).RequestSummary)); + + // One closing runtime warning naming the three dropped lines. + var closing = Assert.Single(logs, e => Extra(e).LogSource == "runtime"); + Assert.Equal("warn", Extra(closing).LogLevel); + Assert.Contains("3 line(s) dropped", Row(closing).RequestSummary); + + // Every log row — the closing one included — precedes the run's anchor row. + var anchorIndex = rows.ToList().FindIndex(e => Row(e).Kind == AuditKind.ScriptRun); + Assert.All(logs, e => Assert.True(rows.ToList().IndexOf(e) < anchorIndex)); + Assert.Equal(logs.Count, anchorIndex); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/SiteRuntimeOptionsValidatorTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/SiteRuntimeOptionsValidatorTests.cs index d8a416ae..6ad2c26a 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/SiteRuntimeOptionsValidatorTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/SiteRuntimeOptionsValidatorTests.cs @@ -147,6 +147,18 @@ public class SiteRuntimeOptionsValidatorTests Assert.Equal(30, new SiteRuntimeOptions().TraceArmWindowSeconds); } + /// A zero cap would drop every log line AND the closing row that reports the drops. + [Fact] + public void ZeroMaxLogLinesPerRun_IsRejected() + { + // Flow Debugger step logs (design 2026-09-09 D7): the per-run cap must be positive. + var result = Validate(new SiteRuntimeOptions { MaxLogLinesPerRun = 0 }); + + Assert.True(result.Failed); + Assert.Contains("MaxLogLinesPerRun", result.FailureMessage); + Assert.Equal(200, new SiteRuntimeOptions().MaxLogLinesPerRun); + } + [Fact] public void ZeroMaxConcurrentRunsPerScript_IsRejected() {