fix(flow-debugger): final-review remediation — 2000-row trace pull, shared ExceptionHeader parser, surrogate-safe clip, wording, alarm source, register renumber (I1/I2/M1-M8)

2026-09-09 13:30:48 -04:00
parent 0bacc3630e
commit 97f01ae98e
21 changed files with 462 additions and 71 deletions
@@ -159,7 +159,8 @@ public class FlowDebugCommandsTests
    /// and canonical <see cref="AuditEvent"/> types with the server's camelCase policy, so
    /// a rename on either fails this test instead of silently blanking a column.
    /// </summary>
-    private static string RealPayload(bool completed, string? errorCode, string? error, bool truncated)
+    private static string RealPayload(
+        bool completed, string? errorCode, string? error, bool truncated, bool logsTruncated = false)
    {
        var root = Guid.NewGuid();
        var child = Guid.NewGuid();
@@ -180,7 +181,7 @@ public class FlowDebugCommandsTests
        };

        var result = new FlowDebugRunResult(root, completed, error, errorCode, events, truncated,
-            new DateTimeOffset(t0), new DateTimeOffset(t0.AddSeconds(1)));
+            new DateTimeOffset(t0), new DateTimeOffset(t0.AddSeconds(1)), logsTruncated);
        return JsonSerializer.Serialize(result, CamelCase);
    }

@@ -241,6 +242,33 @@ public class FlowDebugCommandsTests
        Assert.Contains("audit tree", last.GetProperty("note").GetString());
    }

+    [Fact]
+    public void Projection_LogsTruncatedRun_NotesThatReplayPullsTheRest()
+    {
+        // Final review M8: `logsTruncated` is a SEPARATE signal from `truncated` (the inline
+        // collector sheds low-priority ScriptLog rows before it sheds step rows). The page shows
+        // it; the CLI used to drop it silently.
+        var projected = FlowDebugTableProjection.ProjectEvents(
+            RealPayload(completed: true, null, null, truncated: false, logsTruncated: true));
+
+        using var doc = JsonDocument.Parse(projected);
+        var rows = doc.RootElement.EnumerateArray().ToList();
+        Assert.Equal(5, rows.Count); // the four steps plus the note
+        Assert.Equal("inline log lines capped — replay pulls the rest", rows[^1].GetProperty("note").GetString());
+    }
+
+    [Fact]
+    public void Projection_BothTruncationFlags_AreReportedTogether()
+    {
+        var projected = FlowDebugTableProjection.ProjectEvents(
+            RealPayload(completed: true, null, null, truncated: true, logsTruncated: true));
+
+        using var doc = JsonDocument.Parse(projected);
+        var note = doc.RootElement.EnumerateArray().Last().GetProperty("note").GetString();
+        Assert.Contains("event list truncated", note);
+        Assert.Contains("inline log lines capped — replay pulls the rest", note);
+    }
+
    [Fact]
    public void Projection_LeavesNonMatchingBodiesUntouched()
    {
@@ -254,6 +254,27 @@ public class FlowStepDetailTests : BunitContext
        Assert.NotNull(cut.Find("[data-test=flow-step-exception-copy]"));
    }

+    [Fact]
+    public void WrappedException_TheBlockHeaderNamesTheINNERMOSTType_InFull()
+    {
+        // Final review M1: the panel used to parse the OUTERMOST exception of a " ---> " chain
+        // while the graph node's subtitle showed the innermost — the two now share
+        // ExceptionHeader, which always follows the chain to its end. The panel still shows the
+        // type with its namespace (only the node badge shortens it), and the raw detail is
+        // untouched, so the wrapper is still visible in the <pre>.
+        const string wrapped =
+            "System.AggregateException: One or more errors occurred. (Recipe 42 rejected by Galaxy (code 7)) " +
+            "---> ZB.Scada.RecipeRejectedException: Recipe 42 rejected by Galaxy (code 7)\n" +
+            "   at Submission#0.<<Initialize>>d__0.MoveNext()";
+        var step = ScriptStep(FlowStepOutcome.Failed, "ProcessRecipeDownload", Guid.NewGuid(), [], wrapped);
+        var cut = Render<FlowStepDetail>(p => p.Add(x => x.Step, step));
+
+        var exc = cut.Find("[data-test=flow-step-exception]");
+        Assert.Equal("ZB.Scada.RecipeRejectedException", exc.QuerySelector(".fsd-exc-type")!.TextContent.Trim());
+        Assert.Equal("Recipe 42 rejected by Galaxy (code 7)", exc.QuerySelector(".fsd-exc-message")!.TextContent.Trim());
+        Assert.Contains("System.AggregateException", exc.QuerySelector("pre")!.TextContent);
+    }
+
    [Fact]
    public void OkStepWithLines_OpensOnInput()
    {
@@ -0,0 +1,71 @@
+using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging;
+
+namespace ZB.MOM.WW.ScadaBridge.Commons.Tests.Debugging;
+
+/// <summary>
+/// Final review M1: the ONE parser behind the graph node's exception subtitle and the step
+/// detail panel's exception block. Before it, the panel showed the OUTERMOST exception of a
+/// wrapped chain while the node showed the innermost — the two now agree by construction.
+/// </summary>
+public class ExceptionHeaderTests
+{
+    [Fact]
+    public void Parse_PlainDetail_SplitsTypeFromMessage_AndShortensOnlyWhenAsked()
+    {
+        const string detail = "System.InvalidOperationException: Recipe 42 rejected\n   at X.Y()";
+
+        Assert.Equal(("InvalidOperationException", "Recipe 42 rejected"), ExceptionHeader.Parse(detail, shortenType: true));
+        Assert.Equal(("System.InvalidOperationException", "Recipe 42 rejected"), ExceptionHeader.Parse(detail, shortenType: false));
+    }
+
+    [Fact]
+    public void Parse_WrappedChain_TakesTheINNERMOSTException()
+    {
+        const string detail = "A.Outer: outer ---> B.Middle: middle ---> C.Innermost: the real one\n   at X";
+
+        Assert.Equal(("Innermost", "the real one"), ExceptionHeader.Parse(detail, shortenType: true));
+        // The panel keeps the namespace but still names the innermost exception, not the wrapper.
+        Assert.Equal(("C.Innermost", "the real one"), ExceptionHeader.Parse(detail, shortenType: false));
+    }
+
+    [Fact]
+    public void Parse_GenericType_KeepsTheArityAndArgumentsVerbatim_ShorteningOnlyTheHead()
+    {
+        Assert.Equal(("RecipeException`1[System.String]", "msg"),
+            ExceptionHeader.Parse("MyApp.RecipeException`1[System.String]: msg", shortenType: true));
+        Assert.Equal(("RecipeException`1[System.String]", "msg"),
+            ExceptionHeader.Parse("RecipeException`1[System.String]: msg", shortenType: true));
+    }
+
+    [Fact]
+    public void Parse_ChainMarkerIsMatchedAfterTrimming_SoATrailingMarkerIsNotAChain()
+    {
+        // The first line is trimmed BEFORE the " ---> " chain is walked (behaviour carried over
+        // verbatim from the FlowGraphView original), so a detail ending in the marker keeps it as
+        // part of the message rather than resolving to an empty innermost segment.
+        Assert.Equal(("Outer", "outer --->"), ExceptionHeader.Parse("A.Outer: outer ---> ", shortenType: true));
+    }
+
+    [Fact]
+    public void Parse_LineWithoutAColon_IsAllTypeAndNoMessage()
+    {
+        Assert.Equal(("SomethingWentWrong", string.Empty), ExceptionHeader.Parse("SomethingWentWrong", shortenType: true));
+    }
+
+    [Fact]
+    public void Parse_CrLfDetail_TrimsTheCarriageReturnOffTheFirstLine()
+    {
+        Assert.Equal(("TimeoutException", "took too long"),
+            ExceptionHeader.Parse("System.TimeoutException: took too long\r\n   at X\r\n", shortenType: true));
+    }
+
+    [Theory]
+    [InlineData(null)]
+    [InlineData("")]
+    [InlineData("   ")]
+    public void Parse_NothingUsable_ReturnsNull(string? detail)
+    {
+        Assert.Null(ExceptionHeader.Parse(detail, shortenType: true));
+        Assert.Null(ExceptionHeader.Parse(detail, shortenType: false));
+    }
+}
@@ -0,0 +1,60 @@
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
+using ZB.MOM.WW.Audit;
+using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit;
+
+namespace ZB.MOM.WW.ScadaBridge.InboundAPI.Tests;
+
+/// <summary>
+/// Flow Debugger step logs (design 2026-09-09 D7): the central <c>Log</c> global's per-message cap.
+/// Final review M2 — the site runtime's <c>ScriptLogger.Clip</c> already backed off a char when the
+/// cap landed between the halves of a surrogate pair; this side did not, so an emoji straddling the
+/// boundary left a LONE surrogate on the row (which breaks JSON serialization further down the pipe).
+/// </summary>
+public class InboundScriptLoggerTests
+{
+    private static (InboundScriptLogger Logger, List<AuditEvent> Rows) MakeTraced(int maxLines = 200)
+    {
+        var rows = new List<AuditEvent>();
+        var logger = new InboundScriptLogger(
+            NullLogger.Instance, rows.Add, maxLines, "DelmiaRecipeDownload", Guid.NewGuid(), "central-a");
+        return (logger, rows);
+    }
+
+    [Fact]
+    public void ASurrogatePairStraddlingTheCap_IsDroppedWhole()
+    {
+        var (logger, rows) = MakeTraced();
+        var straddling = new string('x', InboundScriptLogger.MaxMessageChars - 1) + "🚀" + new string('y', 10);
+
+        logger.Info(straddling);
+
+        var message = Assert.Single(rows).AsRow().RequestSummary!;
+        Assert.Equal(InboundScriptLogger.MaxMessageChars, message.Length);
+        Assert.EndsWith("…", message);
+        Assert.DoesNotContain(message, static c => char.IsSurrogate(c));
+    }
+
+    [Fact]
+    public void AnOverlongMessageWithNoSurrogateAtTheBoundary_KeepsTheFullCap()
+    {
+        var (logger, rows) = MakeTraced();
+
+        logger.Info(new string('x', InboundScriptLogger.MaxMessageChars + 500));
+
+        var message = Assert.Single(rows).AsRow().RequestSummary!;
+        Assert.Equal(InboundScriptLogger.MaxMessageChars + 1, message.Length); // cap + the ellipsis
+        Assert.Equal(new string('x', InboundScriptLogger.MaxMessageChars) + "…", message);
+    }
+
+    [Fact]
+    public void AMessageExactlyAtTheCap_PassesThroughUnclipped()
+    {
+        var (logger, rows) = MakeTraced();
+        var exact = new string('x', InboundScriptLogger.MaxMessageChars);
+
+        logger.Info(exact);
+
+        Assert.Equal(exact, Assert.Single(rows).AsRow().RequestSummary);
+    }
+}
@@ -250,6 +250,27 @@ public class FlowDebugRunnerTests
        Assert.Single(result.Events); // just the synthesized write row
    }

+    [Fact]
+    public async Task RunValueChange_AsksTheSiteForItsFullPage_NotTheOldFiveHundredRowCap()
+    {
+        // Final review I1: the site serves ORDER BY OccurredAtUtc ASC LIMIT, so the page is the
+        // OLDEST rows in the window. With step logs a single traced run can emit up to 201
+        // ScriptLog rows, so a 500-row request could push a later spawned run's ScriptRun row off
+        // the end of the page and make this loop report a false NO_TRIGGER_WITHIN_WINDOW. Ask for
+        // the site's own ceiling (SiteStreamGrpcServer.MaxTraceEventsPerPull) instead.
+        var (_, _, puller) = WireValueChange();
+        var maxima = new List<int>();
+        puller.PullAsync("site-a", Arg.Any<IReadOnlyCollection<Guid>>(), Arg.Any<DateTime>(), Arg.Do<int>(maxima.Add), Arg.Any<CancellationToken>())
+            .Returns(Array.Empty<AuditEvent>());
+
+        await Runner().RunValueChangeAsync(_services.BuildServiceProvider(),
+            new FlowDebugRunValueChangeCommand(5, "Status", "Running", WaitSeconds: 3), Deployer, CancellationToken.None);
+
+        Assert.NotEmpty(maxima);
+        Assert.All(maxima, m => Assert.Equal(2000, m));
+        Assert.Equal(2000, FlowDebugRunner.PullTraceEventsMax);
+    }
+
    [Fact]
    public async Task RunValueChange_OutOfScopeSite_IsRefused()
    {
@@ -0,0 +1,89 @@
+using Akka.Actor;
+using Akka.TestKit.Xunit2;
+using Microsoft.CodeAnalysis.CSharp.Scripting;
+using Microsoft.CodeAnalysis.Scripting;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
+using ZB.MOM.WW.ScadaBridge.Commons.Messages.Streaming;
+using ZB.MOM.WW.ScadaBridge.Commons.Types.Flattening;
+using ZB.MOM.WW.ScadaBridge.SiteRuntime.Actors;
+using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
+
+namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Actors;
+
+/// <summary>
+/// Final review M6: an alarm on-trigger run's <c>ScriptRuntimeContext</c> was built without a
+/// <c>sourceScript</c>, so the context's <c>_logTarget</c> — which names the script on every
+/// <c>Log.*</c> line and on the run's trace rows — fell back to the INSTANCE name. The launcher now
+/// passes the same <c>AlarmActor:{alarmName}</c> source key it already uses for this alarm's site
+/// events, from which the context derives the alarm's own name.
+/// </summary>
+public class AlarmScriptLogTargetTests : TestKit, IDisposable
+{
+    private sealed record Entry(LogLevel Level, string Message);
+
+    /// <summary>A minimal recording logger — the alarm path hands its own ILogger down to the script logger.</summary>
+    private sealed class RecordingLogger<T> : ILogger<T>
+    {
+        public List<Entry> Entries { get; } = [];
+
+        public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
+
+        public bool IsEnabled(LogLevel logLevel) => true;
+
+        public void Log<TState>(LogLevel level, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
+        {
+            lock (Entries) Entries.Add(new Entry(level, formatter(state, exception)));
+        }
+    }
+
+    private readonly SharedScriptLibrary _sharedLibrary = new(
+        new ScriptCompilationService(NullLogger<ScriptCompilationService>.Instance),
+        NullLogger<SharedScriptLibrary>.Instance);
+
+    void IDisposable.Dispose() => Shutdown();
+
+    [Fact]
+    public void AlarmOnTriggerRun_AttributesItsLogLinesToTheALARM_NotJustTheInstance()
+    {
+        var options = new SiteRuntimeOptions
+        {
+            ScriptExecutionTimeoutSeconds = 10,
+            MaxScriptCallDepth = 10,
+        };
+        var scriptOptions = ScriptOptions.Default
+            .WithReferences(typeof(object).Assembly, typeof(Enumerable).Assembly, typeof(ScriptGlobals).Assembly)
+            .WithImports("System", "System.Threading.Tasks");
+        var compiled = CSharpScript.Create<object?>("Log.Info(\"alarm handler ran\"); return null;", scriptOptions, typeof(ScriptGlobals));
+        compiled.Compile();
+
+        var logger = new RecordingLogger<AlarmActor>();
+        using var scheduler = new ScriptExecutionScheduler(1);
+        var config = new ResolvedAlarm
+        {
+            CanonicalName = "HighTemp",
+            TriggerType = "ValueMatch",
+            TriggerConfiguration = "{\"attributeName\":\"Status\",\"matchValue\":\"Critical\"}",
+            PriorityLevel = 100,
+        };
+        var alarm = ActorOfAsTestActorRef<AlarmActor>(
+            Props.Create(() => new AlarmActor(
+                "HighTemp", "Inst1", CreateTestProbe().Ref, config, compiled, _sharedLibrary, options,
+                logger, null, null, null, null, null, scheduler, null)),
+            "alarm-logtarget-" + Guid.NewGuid().ToString("N"));
+
+        alarm.Tell(new AttributeValueChanged("Inst1", "Status", "Status", "Critical", "Good", DateTimeOffset.UtcNow));
+
+        AwaitAssert(
+            () =>
+            {
+                Entry[] snapshot;
+                lock (logger.Entries) snapshot = [.. logger.Entries];
+                // "[script] {Instance}/{Script} {ExecutionId}: {Message}" — the script half is the
+                // alarm's name because the launcher passed "AlarmActor:HighTemp" as the source.
+                Assert.Contains(snapshot, e => e.Message.StartsWith("[script] Inst1/HighTemp ", StringComparison.Ordinal)
+                    && e.Message.EndsWith(": alarm handler ran", StringComparison.Ordinal));
+            },
+            TimeSpan.FromSeconds(15));
+    }
+}
@@ -159,7 +159,9 @@ public class ScriptLoggerTests
        var closing = rows[^1];
        Assert.Equal("warn", closing.Level);
        Assert.Equal("runtime", closing.Source);
-        Assert.Contains("2 line(s)", closing.Message);
+        // M3: worded identically to the central InboundScriptLogger closing row.
+        Assert.Contains("2 further log line(s) were not captured", closing.Message);
+        Assert.Contains("ScadaBridge:SiteRuntime:MaxLogLinesPerRun = 3", closing.Message);
        Assert.Null(closing.StepEventId);

        logger.FlushDropped();
@@ -302,7 +304,7 @@ public class ScriptLoggerTests

        Assert.Equal(2, rows.Count);
        logger.FlushDropped();
-        Assert.Contains("1 line(s)", rows[^1].Message);
+        Assert.Contains("1 further log line(s) were not captured", rows[^1].Message);
    }

    [Fact]
@@ -149,7 +149,7 @@ public class ScriptRunLauncherTraceTests : TestKit, IDisposable
        // 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);
+        Assert.Contains("3 further log line(s) were not captured", 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);
@@ -701,7 +701,7 @@ public class ScriptRuntimeContextTraceEmissionTests : TestKit
        var extra = ScriptTraceExtra.TryParse(closing.Extra)!;
        Assert.Equal("warn", extra.LogLevel);
        Assert.Equal("runtime", extra.LogSource);
-        Assert.Contains("1 line(s) dropped", closing.RequestSummary);
+        Assert.Contains("1 further log line(s) were not captured", closing.RequestSummary);
    }

    /// <summary>
@@ -780,7 +780,7 @@ public class ScriptRuntimeContextTraceEmissionTests : TestKit
        Assert.Equal(["from the caller", "shared"], rows.Select(e => Row(e).RequestSummary));

        parent.Log.FlushDropped();
-        Assert.Contains("2 line(s) dropped", Row(collector.Snapshot()[^1]).RequestSummary);
+        Assert.Contains("2 further log line(s) were not captured", Row(collector.Snapshot()[^1]).RequestSummary);
    }

    /// <summary>