Merge wt/step-logs-t6: Task 6

2026-09-09 12:32:34 -04:00
parent 8ba1a0e2f8 750c542c2f
commit 21b691e45a
5 changed files with 223 additions and 6 deletions
@@ -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;
+
+/// <summary>
+/// Flow Debugger step logs (design 2026-09-09 D3/D7) at the launcher boundary: the
+/// <c>ScriptRun</c> 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 <c>SiteRuntimeOptions.MaxLogLinesPerRun</c> 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.
+/// </summary>
+public class ScriptRunLauncherTraceTests : TestKit, IDisposable
+{
+    /// <summary>Own pool per class (#18 seam), so a wedged body cannot strand the process-wide one.</summary>
+    private readonly ScriptExecutionScheduler _scheduler = new(4);
+    private readonly SharedScriptLibrary _sharedLibrary;
+
+    public ScriptRunLauncherTraceTests()
+        => _sharedLibrary = new SharedScriptLibrary(
+            new ScriptCompilationService(NullLogger<ScriptCompilationService>.Instance),
+            NullLogger<SharedScriptLibrary>.Instance);
+
+    void IDisposable.Dispose()
+    {
+        Shutdown();
+        _scheduler.Dispose();
+    }
+
+    // ── helpers ──────────────────────────────────────────────────────────────────
+
+    private static Script<object?> 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<object?>(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)!;
+
+    /// <summary>Runs one traced script to completion and returns the reply's inline trace rows.</summary>
+    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<ScriptCallResult>(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);
+    }
+}
@@ -147,6 +147,18 @@ public class SiteRuntimeOptionsValidatorTests
        Assert.Equal(30, new SiteRuntimeOptions().TraceArmWindowSeconds);
    }

+    /// <summary>A zero cap would drop every log line AND the closing row that reports the drops.</summary>
+    [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()
    {