Files
ScadaBridge/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Debugging/FlowGraphBuilderLogLineTests.cs
T
Joseph Doherty c810bd0f7c feat(logging): bridge Akka logging to Serilog and copy traced runs' node-log lines into the Flow Debugger (ScadaBridge#120, #56)
#120: Akka ILoggingAdapter lines used to bypass Serilog and go to stdout only.
- BuildHocon sets akka.loggers = [Host.Actors.SerilogAkkaLogger] and keeps akka.loglevel = INFO,
  so Akka Debug chatter is still filtered at the adapter. The INFO+ lines that used to reach
  stdout now go through the Serilog pipeline instead, with no extra volume.
- Lines reach the file sinks with the node enrichers. SourceContext is the logging class's full
  name, AkkaSource is the actor path, Akka's own timestamp is kept, and format arguments become
  structured properties.
- The Akka logger actor writes on its own thread, after the logging actor's LogContext is gone.
  To keep the ExecutionId, the two DCL actors log through ExecutionAwareLogging.GetLogger(Context),
  which records ExecutionLogContext.Current (a new AsyncLocal mirror of the pushed id) in an
  ExecutionTaggedLogMessage. The logger actor pushes that id again while it writes the line.

#56 remainder (coordinator decision: no replicated schema change):
- The host pipeline gains ExecutionLogCaptureSink.
- While a run is traced, its step logger registers its ExecutionId: the site ScriptLogger from the
  launcher (plus each inline CallShared child id), and the central InboundScriptLogger from the
  executor.
- Each tagged line becomes a ScriptLog row with LogSource "node" and the new
  ScriptTraceExtra.LogCategory.
- The rows count against the existing MaxLogLinesPerRun cap, are clipped at 2 000 chars, ride the
  low-priority collector lane and pass the same redactor. Untraced runs cost one volatile read.
- Lines are never copied twice. The step loggers' own forwards run inside
  ExecutionLogCapture.Suppress(), and the sink suppresses itself while it calls a target. The
  registration is declared inside the launcher's and executor's try, so it ends before the catch
  blocks log the outcome, and FlushDropped closes it.
- FlowGraphBuilder lists node lines in FlowGraph.NodeLogs and never folds them onto a step.
- The Flow Debugger shows them in a Node log card (FlowNodeLogPanel): grouped per execution under
  its run step, with an All | Warn + filter. Live and Replay both read the same rows, so site
  scope and role rules apply unchanged.
- CLI --show-logs prints them as a trailing block.

Tests: Commons ExecutionLogCaptureTests, ExecutionLogContext.Current, FlowGraphBuilder node lines.
SiteRuntime NodeLogCaptureTests covers cross-actor capture via the launcher, untraced runs
capturing nothing, no double capture of script and runtime lines or of the launcher failure line,
the shared cap, collector redaction, shared-script child ids and FlushDropped closing capture.
InboundNodeLogCaptureTests covers the central path. DCL ExecutionAwareLoggingTests covers the
DataConnectionActor write-path Debug line being tagged and an uncorrelated line not being tagged.
Host SerilogAkkaLoggerTests covers mapping, the ExecutionId crossing the logger hop, HOCON,
ActorSystem boot and the Akka line reaching a traced run's step log end to end. Host
LoggerConfigurationTests checks that the sink is wired. bUnit FlowNodeLogPanelTests and a CLI
projection test cover the UI and CLI. Every new assertion was mutation-proven.

Docs: step-logs design section 12, Component-SiteRuntime, CentralUI, InboundAPI, Host, CLI README,
CLAUDE.md.

Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
2026-11-10 06:12:34 -05:00

259 lines
12 KiB
C#

using ZB.MOM.WW.Audit;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums;
namespace ZB.MOM.WW.ScadaBridge.Commons.Tests.Debugging;
/// <summary>
/// Step-logs design 2026-09-09 D2: a <c>ScriptTrace.ScriptLog</c> row is never a node — it folds onto the
/// step its <c>StepEventId</c> names, else onto its execution's anchor (<c>ScriptRun</c> /
/// <c>InboundRequest</c> / <c>RouteCall</c>), else its execution's first non-<c>Response</c> step, else it is
/// dropped and counted in <see cref="FlowGraph.UnattachedLogLines"/>.
/// </summary>
public class FlowGraphBuilderLogLineTests
{
private static readonly DateTime T0 = new(2026, 9, 9, 12, 0, 0, DateTimeKind.Utc);
private static AuditEvent Run(Guid execution, Guid? parent = null, int ms = 0) =>
ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.ScriptRun, AuditStatus.Delivered,
occurredAtUtc: T0.AddMilliseconds(ms), actor: "SomeScript", target: "SomeScript", sourceNode: "node-a",
executionId: execution, parentExecutionId: parent, sourceSiteId: "site-a", sourceInstanceId: "M1",
durationMs: 100, extra: new ScriptTraceExtra { TriggerKind = "call" }.ToJson());
private static AuditEvent Write(Guid execution, Guid? eventId = null, int ms = 10) =>
ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.AttributeWrite, AuditStatus.Delivered,
eventId: eventId, occurredAtUtc: T0.AddMilliseconds(ms), actor: "SomeScript", target: "M1.Flag",
sourceNode: "node-a", executionId: execution, sourceSiteId: "site-a", sourceInstanceId: "M1", durationMs: 2,
extra: new ScriptTraceExtra { Writes = [new AttributeWriteDetail("M1.Flag", "true", true, null)] }.ToJson());
private static AuditEvent Inbound(Guid execution, int ms = 0) =>
ScadaBridgeAuditEventFactory.Create(AuditChannel.ApiInbound, AuditKind.InboundRequest, AuditStatus.Delivered,
occurredAtUtc: T0.AddMilliseconds(ms), actor: "some-key", target: "SomeMethod", sourceNode: "central-a",
executionId: execution, durationMs: 50, requestSummary: "{}", responseSummary: "{\"ok\":true}");
private static AuditEvent RouteCallRoot(Guid execution, int ms = 0) =>
ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.RouteCall, AuditStatus.Delivered,
occurredAtUtc: T0.AddMilliseconds(ms), actor: "flow-debugger", target: "M1.SomeScript", sourceNode: "central-a",
executionId: execution, durationMs: 120);
private static AuditEvent ApiOut(Guid execution, Guid eventId, int ms = 20) =>
ScadaBridgeAuditEventFactory.Create(AuditChannel.ApiOutbound, AuditKind.ApiCall, AuditStatus.Delivered,
eventId: eventId, occurredAtUtc: T0.AddMilliseconds(ms), actor: "SomeScript", target: "ERP/orders",
sourceNode: "node-a", executionId: execution, sourceSiteId: "site-a", durationMs: 30);
private static AuditEvent Line(Guid execution, Guid? step = null, int? seq = null, string level = "info",
int ms = 5, string message = "hello") =>
ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.ScriptLog, AuditStatus.Delivered,
occurredAtUtc: T0.AddMilliseconds(ms), actor: "SomeScript", target: "SomeScript", sourceNode: "node-a",
executionId: execution, sourceSiteId: "site-a", sourceInstanceId: "M1", requestSummary: message,
extra: new ScriptTraceExtra { LogLevel = level, LogSource = "script", StepEventId = step, Seq = seq }.ToJson());
private static FlowStep StepOf(FlowGraph graph, FlowStepKind kind) => Assert.Single(graph.Steps, s => s.Kind == kind);
/// <summary>Verifies that a log line carrying a step event id attaches to that step.</summary>
[Fact]
public void LogLine_WithStepEventId_AttachesToThatStep()
{
var execution = Guid.NewGuid();
var writeId = Guid.NewGuid();
var graph = FlowGraphBuilder.Build([Run(execution), Write(execution, writeId), Line(execution, step: writeId)]);
var write = StepOf(graph, FlowStepKind.AttributeWrite);
var line = Assert.Single(write.Logs!);
Assert.Equal("hello", line.Message);
Assert.Null(StepOf(graph, FlowStepKind.ScriptRun).Logs);
}
/// <summary>Verifies that a log line without a step id attaches to the execution anchor.</summary>
[Fact]
public void LogLine_WithoutStepId_AttachesToTheExecutionAnchor()
{
var execution = Guid.NewGuid();
var graph = FlowGraphBuilder.Build([Run(execution), Write(execution), Line(execution)]);
Assert.Single(StepOf(graph, FlowStepKind.ScriptRun).Logs!);
Assert.Null(StepOf(graph, FlowStepKind.AttributeWrite).Logs);
}
/// <summary>Verifies that a central log line attaches to the inbound row rather than the response.</summary>
[Fact]
public void CentralLine_AttachesToInboundRow_NotResponse()
{
var execution = Guid.NewGuid();
var graph = FlowGraphBuilder.Build([Inbound(execution), Line(execution)]);
Assert.Single(StepOf(graph, FlowStepKind.InboundRequest).Logs!);
Assert.Null(StepOf(graph, FlowStepKind.Response).Logs);
}
/// <summary>Verifies that a script-entry log line attaches to the route-call root.</summary>
[Fact]
public void ScriptEntryLine_AttachesToRouteCallRoot()
{
var execution = Guid.NewGuid();
var graph = FlowGraphBuilder.Build([RouteCallRoot(execution), Line(execution)]);
Assert.Single(StepOf(graph, FlowStepKind.RouteCall).Logs!);
}
/// <summary>Verifies that a log line with an unknown step id falls back to the anchor.</summary>
[Fact]
public void LogLine_UnknownStepId_FallsBackToAnchor()
{
var execution = Guid.NewGuid();
var graph = FlowGraphBuilder.Build([Run(execution), Line(execution, step: Guid.NewGuid())]);
Assert.Single(StepOf(graph, FlowStepKind.ScriptRun).Logs!);
Assert.Equal(0, graph.UnattachedLogLines);
}
/// <summary>Verifies that a log line with no anchor falls back to the first step.</summary>
[Fact]
public void LogLine_NoAnchor_FallsBackToFirstStep()
{
var execution = Guid.NewGuid();
var graph = FlowGraphBuilder.Build([Write(execution), Line(execution)]);
Assert.Single(StepOf(graph, FlowStepKind.AttributeWrite).Logs!);
Assert.Equal(0, graph.UnattachedLogLines);
}
/// <summary>Verifies that a log line whose execution has no step is counted as unattached.</summary>
[Fact]
public void LogLine_NoStepInExecution_IsCountedUnattached()
{
var execution = Guid.NewGuid();
var graph = FlowGraphBuilder.Build([Run(execution), Line(Guid.NewGuid())]);
Assert.Equal(1, graph.UnattachedLogLines);
Assert.All(graph.Steps, s => Assert.True(s.Logs is null or { Count: 0 }));
}
/// <summary>Verifies that building from log lines only returns an empty graph with the unattached count.</summary>
[Fact]
public void Build_LinesOnly_ReturnsEmptyGraphWithUnattachedCount()
{
var graph = FlowGraphBuilder.Build([Line(Guid.NewGuid()), Line(Guid.NewGuid())], logsTruncated: true);
Assert.Empty(graph.Steps);
Assert.Empty(graph.Edges);
Assert.Equal(2, graph.UnattachedLogLines);
Assert.True(graph.LogsTruncated);
}
/// <summary>Verifies that lines within the same millisecond are ordered by sequence with null sequences last.</summary>
[Fact]
public void Lines_OrderBySeqWithinSameMillisecond_NullSeqLast()
{
var execution = Guid.NewGuid();
var graph = FlowGraphBuilder.Build(
[
Run(execution),
Line(execution, seq: 3, ms: 5, message: "three"),
Line(execution, seq: 1, ms: 5, message: "one"),
Line(execution, seq: null, ms: 5, message: "null"),
Line(execution, seq: 2, ms: 5, message: "two"),
]);
var logs = StepOf(graph, FlowStepKind.ScriptRun).Logs!;
Assert.Equal(new int?[] { 1, 2, 3, null }, logs.Select(l => l.Seq).ToArray());
Assert.Equal(new[] { "one", "two", "three", "null" }, logs.Select(l => l.Message).ToArray());
}
/// <summary>Verifies that log lines never become graph steps.</summary>
[Fact]
public void LogLines_NeverBecomeSteps()
{
var execution = Guid.NewGuid();
var events = new List<AuditEvent> { Run(execution) };
for (var i = 0; i < 5; i++)
events.Add(Line(execution, seq: i, ms: 1 + i, message: $"line {i}"));
var lineIds = events.Skip(1).Select(e => e.EventId).ToHashSet();
var graph = FlowGraphBuilder.Build(events);
var step = Assert.Single(graph.Steps);
Assert.Equal(FlowStepKind.ScriptRun, step.Kind);
Assert.Equal(5, step.Logs!.Count);
Assert.DoesNotContain(graph.Edges, e => lineIds.Contains(e.FromEventId) || lineIds.Contains(e.ToEventId));
}
/// <summary>Verifies that the builder passes the logs-truncated flag through to the graph.</summary>
[Fact]
public void Build_PassesLogsTruncatedThrough()
{
var execution = Guid.NewGuid();
var graph = FlowGraphBuilder.Build([Run(execution)], truncated: false, logsTruncated: true);
Assert.True(graph.LogsTruncated);
Assert.False(graph.Truncated);
}
/// <summary>Verifies that a log line on a folded outbound step attaches by the first row id.</summary>
[Fact]
public void LogLine_OnFoldedOutboundStep_AttachesByFirstRowId()
{
var execution = Guid.NewGuid();
var callId = Guid.NewGuid();
var graph = FlowGraphBuilder.Build([Run(execution), ApiOut(execution, callId), Line(execution, step: callId)]);
var call = StepOf(graph, FlowStepKind.ApiCall);
Assert.Equal(callId, call.EventId);
Assert.Single(call.Logs!);
Assert.Null(StepOf(graph, FlowStepKind.ScriptRun).Logs);
}
private static AuditEvent NodeLine(Guid execution, int ms, int? seq, string message, string category = "Acme.Dcl") =>
ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.ScriptLog, AuditStatus.Delivered,
occurredAtUtc: T0.AddMilliseconds(ms), actor: "SomeScript", target: "SomeScript", sourceNode: "node-a",
executionId: execution, sourceSiteId: "site-a", sourceInstanceId: "M1", requestSummary: message,
extra: new ScriptTraceExtra { LogLevel = "warn", LogSource = "node", LogCategory = category, Seq = seq }.ToJson());
/// <summary>
/// ScadaBridge#56: node lines are listed on the graph in time order (seq breaking ties), never folded
/// onto a step — not even the anchor — and never counted as unattached, while script lines still fold.
/// </summary>
[Fact]
public void NodeLines_AreListedOnTheGraph_NotFoldedOntoSteps()
{
var execution = Guid.NewGuid();
var orphan = Guid.NewGuid(); // an execution with no step at all
var graph = FlowGraphBuilder.Build(
[
Run(execution), Line(execution),
NodeLine(execution, ms: 30, seq: 2, message: "late"),
NodeLine(execution, ms: 20, seq: 9, message: "early-b"),
NodeLine(execution, ms: 20, seq: 1, message: "early-a"),
NodeLine(orphan, ms: 40, seq: 1, message: "orphan"),
]);
Assert.Equal(["early-a", "early-b", "late", "orphan"], graph.NodeLogs!.Select(l => l.Message));
Assert.All(graph.NodeLogs!, l => Assert.True(l.IsNodeLine));
Assert.Equal("Acme.Dcl", graph.NodeLogs![0].Category);
var anchorLogs = StepOf(graph, FlowStepKind.ScriptRun).Logs!;
Assert.Equal("hello", Assert.Single(anchorLogs).Message);
Assert.Equal(0, graph.UnattachedLogLines);
}
/// <summary>A trace with no node lines has a null <see cref="FlowGraph.NodeLogs"/>, including a step-less one.</summary>
[Fact]
public void NoNodeLines_LeavesNodeLogsNull()
{
var execution = Guid.NewGuid();
Assert.Null(FlowGraphBuilder.Build([Run(execution), Line(execution)]).NodeLogs);
Assert.Single(FlowGraphBuilder.Build([NodeLine(execution, 1, 1, "only")]).NodeLogs!);
}
}