From ee8a8e9d3d03dd0caa34a87d26ccd7cf3b5febf4 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 9 Sep 2026 12:10:17 -0400 Subject: [PATCH] =?UTF-8?q?fix(site-runtime):=20step-log=20review=20?= =?UTF-8?q?=E2=80=94=20trace-flag-gated=20ES=20step=20scope,=20shared-scri?= =?UTF-8?q?pt=20Log,=20formatter=20guard?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Task 5 code-review follow-ups: - I1: ExternalSystemHelper gates its TraceStepScope on a new isTraced ctor arg (default false for direct construction), not on `_traceSink is not null` — a traced run without an inline collector still writes durable ScriptLog rows that must name their step. - I2 (design §5): an inline shared script now SHARES its caller's ScriptLogger via the new `sharedLog` ctor param — one line cap, one anchor, one closing row. Consequence documented on the Log property: a shared script's lines carry the PARENT run's ExecutionId and land on the parent's ScriptRun node. - M3: TraceCapturingLogger swallows a throwing formatter — most of what it captures is best-effort "audit write failed" warnings logged from inside a catch block, and a formatting exception must not escape that path. - Tests: ApiCall step attribution, traced-without-collector, shared-script logger sharing, nested batch/wait scope attribution + unwind, throwing formatter; test (c) now also pins the anti-recursion property (EmitLog must log through the undecorated logger). CompileSurfaceParityTests stays red until Task 7 mirrors Log on ScriptCompileSurface. --- .../Scripts/ScriptRuntimeContext.cs | 56 ++++++-- .../Scripts/TraceCapturingLogger.cs | 18 ++- .../ScriptRuntimeContextTraceEmissionTests.cs | 125 ++++++++++++++++++ .../Scripts/TraceCapturingLoggerTests.cs | 21 +++ 4 files changed, 209 insertions(+), 11 deletions(-) diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs index 84ddf4da..c15a724c 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs @@ -237,6 +237,14 @@ public class ScriptRuntimeContext /// /// Bounded per run (D7) and never throws into the script — see /// . + /// + /// An inline shared script SHARES its caller's logger (design §5): a context built + /// by is handed this same instance rather than + /// making its own, so the caller and every shared script it calls share ONE per-run line cap and + /// ONE closing "dropped lines" row. The consequence to know: a shared script's lines carry the + /// PARENT run's ExecutionId and therefore land on the parent's ScriptRun node in + /// the Flow Debugger — not on the shared script's own execution node, even though its + /// ApiCall/DbWrite/step rows still chain under their own execution. /// public ScriptLogger Log { get; } @@ -296,6 +304,12 @@ public class ScriptRuntimeContext /// — mirrors SiteRuntimeOptions.MaxLogLinesPerRun, which the script run launcher passes /// in. Values below 1 are clamped to 1: a mis-set option must not make every script run throw. /// + /// + /// Step logs (design §5): an existing to adopt as + /// instead of creating one — supplied only by + /// , so an inline shared script shares its + /// caller's line cap and anchor. Null (the default) creates this run's own logger. + /// public ScriptRuntimeContext( IActorRef instanceActor, SharedScriptLibrary sharedScriptLibrary, @@ -320,7 +334,8 @@ public class ScriptRuntimeContext CancellationToken scriptTimeoutToken = default, bool isTraced = false, FlowTraceCollector? traceCollector = null, - int maxLogLinesPerRun = 200) + int maxLogLinesPerRun = 200, + ScriptLogger? sharedLog = null) { _instanceActor = instanceActor; _sharedScriptLibrary = sharedScriptLibrary; @@ -368,10 +383,14 @@ public class ScriptRuntimeContext ? _instanceName // "ScriptActor:Foo" / "AlarmActor:Foo" -> "Foo"; a bare name is unchanged (IndexOf -1). : _sourceScript[(_sourceScript.IndexOf(':') + 1)..]; - Log = new ScriptLogger( + // An inline shared script adopts its caller's logger (design §5) — one counter, one anchor, + // one closing row for the whole inline chain. Everyone else builds their own. + Log = sharedLog ?? new ScriptLogger( logger, isTraced ? EmitLog : null, _maxLogLinesPerRun, _instanceName, _logTarget, _executionId); if (isTraced) { + // The child's OWN undecorated logger, decorated over the SHARED sink: the capturing + // decorator is per-context (it must not be handed on), the sink behind it is not. _logger = new TraceCapturingLogger(logger, Log); } } @@ -480,9 +499,11 @@ public class ScriptRuntimeContext // shared script shares the same flag AND the same inline sink. isTraced: _isTraced, traceCollector: _traceCollector, - // Step logs (D7): the inline shared script is its own execution node with its own - // Log counter, but it inherits the same per-run cap. - maxLogLinesPerRun: _maxLogLinesPerRun); + maxLogLinesPerRun: _maxLogLinesPerRun, + // Step logs (design §5): the inline shared script is its own execution node for step + // rows, but it SHARES this run's Log — one line cap and one anchor for the whole + // inline chain, so its lines carry this run's ExecutionId. + sharedLog: Log); } /// @@ -1059,7 +1080,9 @@ public class ScriptRuntimeContext // it onto SiteCallOperational.SourceNode. _sourceNode, // Flow Debugger: the outbound rows ride the inline collector (null when untraced). - traceSink: _traceSink); + traceSink: _traceSink, + // Step logs (D6): the run's trace flag — the authority for the sync Call's step scope. + isTraced: _isTraced); /// /// Provides access to database operations. @@ -1317,6 +1340,15 @@ public class ScriptRuntimeContext /// private readonly Action? _traceSink; + /// + /// Step logs (design 2026-09-09 D6): whether the owning run is traced. The authority for + /// opening a around . Deliberately NOT + /// : the sink is null whenever the run has no inline collector, + /// which is a different question from "is this run traced" — a traced run without a + /// collector still writes durable ScriptLog rows that must name their step. + /// + private readonly bool _isTraced; + /// /// Initializes a new external system helper for script API calls. /// @@ -1331,6 +1363,7 @@ public class ScriptRuntimeContext /// Optional identifier of the parent execution (for routed calls). /// Optional cluster node identifier (node-a/node-b) for audit stamping. /// Flow Debugger inline collector — receives the same each emit hands to the writer/forwarder; null when untraced. + /// Step logs (design D6): true when the owning run is traced, so pre-mints its row id and publishes it as the ambient step. Defaults to false for direct (test) construction. // Internal constructor for tests living in ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests // (via InternalsVisibleTo). Production sites resolve the helper through // ScriptRuntimeContext.ExternalSystem. @@ -1354,7 +1387,8 @@ public class ScriptRuntimeContext ICachedCallTelemetryForwarder? cachedForwarder = null, Guid? parentExecutionId = null, string? sourceNode = null, - Action? traceSink = null) + Action? traceSink = null, + bool isTraced = false) { _client = client; _instanceName = instanceName; @@ -1367,6 +1401,7 @@ public class ScriptRuntimeContext _parentExecutionId = parentExecutionId; _sourceNode = sourceNode; _traceSink = GuardTraceSink(traceSink, logger); + _isTraced = isTraced; } /// @@ -1395,9 +1430,10 @@ public class ScriptRuntimeContext var startTicks = Stopwatch.GetTimestamp(); // Step logs (design D6): pre-mint this call's audit row id and make it the ambient step // so the helper's own warnings — and anything the client logs through this context — - // are attributed to the API-call node. The trace sink is non-null exactly when the run - // is traced with an inline collector; an untraced run mints nothing and opens no scope. - Guid? stepId = _traceSink is not null ? Guid.NewGuid() : null; + // are attributed to the API-call node. Gated on the run's trace flag, NOT on the + // presence of an inline collector: a traced run without one still writes durable + // ScriptLog rows that need the step id. Untraced mints nothing and opens no scope. + Guid? stepId = _isTraced ? Guid.NewGuid() : null; using var step = stepId is { } callStepId ? TraceStepScope.Enter(callStepId) : null; ExternalCallResult? result = null; Exception? thrown = null; diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs index ed71e6d0..ee485e09 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs @@ -74,6 +74,22 @@ public sealed class TraceCapturingLogger : ILogger _ => "error", }; - _sink.Runtime(name, formatter(state, exception), exception); + string message; + try + { + message = formatter(state, exception); + } + catch + { + // Deliberate swallow: formatting is the CALLER's code, and a great many of the entries + // captured here are the runtime's own best-effort "audit write failed" warnings logged + // from inside a catch block. A throwing formatter escaping this decorator would replace + // the original failure with a formatting exception on a path whose whole contract is + // that it never throws. The line is dropped; the inner logger already saw (or refused) + // it above, unchanged. + return; + } + + _sink.Runtime(name, message, exception); } } diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRuntimeContextTraceEmissionTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRuntimeContextTraceEmissionTests.cs index 917a717b..914847ff 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRuntimeContextTraceEmissionTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRuntimeContextTraceEmissionTests.cs @@ -621,6 +621,12 @@ public class ScriptRuntimeContextTraceEmissionTests : TestKit var collector = new FlowTraceCollector(); // The throwing writer makes EmitTrace log its best-effort "write failed" warning while the // AttributeWrite step scope is open — exactly the runtime line D6 exists to attribute. + // + // It also PINS THE ANTI-RECURSION PROPERTY: EmitLog's own write fails against this writer + // too, so its "log-line write failed" warning must go to the UNDECORATED logger. Routed + // through the capturing decorator instead, each warning would emit another row whose write + // fails again — an unbounded loop, and this test would hang or blow the row count rather + // than see exactly one ScriptLog row. var ctx = CreateContext(probe.Ref, new ThrowingAuditWriter(), traced: true, collector); var call = ctx.SetAttribute("Setpoint", "42"); @@ -697,4 +703,123 @@ public class ScriptRuntimeContextTraceEmissionTests : TestKit Assert.Equal("runtime", extra.LogSource); Assert.Contains("1 line(s) dropped", closing.RequestSummary); } + + /// + /// Review I1: the sync ExternalSystem.Call pre-mints its ApiCall row id and + /// publishes it as the ambient step, so a warning logged while the call is in flight names + /// that node. Provoked the same way as the write case — a writer that throws makes the + /// helper's own best-effort "audit write threw" warning fire inside the scope. + /// + [Fact] + public async Task RuntimeWarning_InsideATracedExternalCall_IsAttributedToTheApiCallStep() + { + var collector = new FlowTraceCollector(); + var ctx = CreateContext(CreateTestProbe().Ref, new ThrowingAuditWriter(), traced: true, collector, + externalSystemClient: SyncClient(new ExternalCallResult(true, "{}", null)).Object); + + var result = await ctx.ExternalSystem.Call("ERP", "GetOrder"); + + Assert.True(result.Success); + var rows = collector.Snapshot(); + var call = rows.Single(e => Row(e).Kind == AuditKind.ApiCall); + var log = rows.Single(e => Row(e).Kind == AuditKind.ScriptLog); + var extra = ScriptTraceExtra.TryParse(Row(log).Extra)!; + Assert.Equal("runtime", extra.LogSource); + Assert.Equal(call.EventId, extra.StepEventId); + } + + /// + /// Review I1: the step scope is gated on the run's TRACE FLAG, not on the presence of an + /// inline collector — a traced run without one still writes durable ScriptLog rows that + /// have to name their step. + /// + [Fact] + public async Task TracedExternalCall_WithoutACollector_StillNamesTheApiCallStep() + { + var writer = new CapturingAuditWriter(); + var ctx = CreateContext(CreateTestProbe().Ref, writer, traced: true, collector: null, + externalSystemClient: SyncClient(new ExternalCallResult(true, "{}", null)).Object); + + await ctx.ExternalSystem.Call("ERP", "GetOrder"); + ctx.Log.Info("after the call, outside any scope"); + + var call = writer.Events.Single(e => Row(e).Kind == AuditKind.ApiCall); + // The line above is outside the scope, so it falls back to the anchor; what this pins is + // that the call's row id was minted and published at all on a collector-less traced run. + Assert.NotEqual(Guid.Empty, call.EventId); + var log = writer.Events.Single(e => Row(e).Kind == AuditKind.ScriptLog); + Assert.Null(ScriptTraceExtra.TryParse(Row(log).Extra)!.StepEventId); + } + + /// + /// Review I2 (design §5): an inline shared script SHARES its caller's + /// — one counter, one anchor. Its lines therefore carry the PARENT run's ExecutionId and + /// land on the parent's ScriptRun node, even though its own step rows chain under its own + /// execution. + /// + [Fact] + public void SharedScriptChild_SharesTheCallersLogger_ExecutionIdAndCap() + { + var writer = new CapturingAuditWriter(); + var collector = new FlowTraceCollector(); + var parent = CreateContext(CreateTestProbe().Ref, writer, traced: true, collector, maxLogLinesPerRun: 2); + var child = parent.CreateChildContextForSharedScript(1); + + Assert.Same(parent.Log, child.Log); + Assert.NotEqual(parent.ExecutionId, child.ExecutionId); + + parent.Log.Info("from the caller"); + child.Log.Info("shared"); + // Third line from either side is over the SHARED cap of 2. + child.Log.Info("dropped"); + parent.Log.Info("also dropped"); + + var rows = collector.Snapshot(); + Assert.Equal(2, rows.Count); + Assert.All(rows, e => Assert.Equal(parent.ExecutionId, Row(e).ExecutionId)); + 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); + } + + /// + /// Review item 4: step scopes NEST — the batch leg's lines name the batch row, the wait leg's + /// name the wait row, and both unwind so a later line falls back to the run anchor. The + /// throwing writer is again what provokes a runtime line inside each leg. + /// + [Fact] + public async Task NestedStepScopes_AttributeEachLegSeparately_AndUnwind() + { + var probe = CreateTestProbe(); + var collector = new FlowTraceCollector(); + var ctx = CreateContext(probe.Ref, new ThrowingAuditWriter(), traced: true, collector); + + var call = ctx.WriteBatchAndWait( + new Dictionary { ["Recipe"] = "R-17" }, + "Trigger", "1", "Ack", "1", TimeSpan.FromSeconds(3)); + + var batchReq = probe.ExpectMsg(TimeSpan.FromSeconds(5)); + probe.Reply(new WriteAttributeBatchResponse(batchReq.CorrelationId, true, null)); + var waitReq = probe.ExpectMsg(TimeSpan.FromSeconds(5)); + probe.Reply(new WaitForAttributeResponse(waitReq.CorrelationId, Matched: true, "1", "Good", TimedOut: false)); + Assert.True(await call); + + // Both scopes have unwound by the time the run continues. + ctx.Log.Info("after both legs"); + + var rows = collector.Snapshot(); + var write = rows.Single(e => Row(e).Kind == AuditKind.AttributeWrite); + var wait = rows.Single(e => Row(e).Kind == AuditKind.AttributeWait); + Assert.NotEqual(write.EventId, wait.EventId); + + var logs = rows.Where(e => Row(e).Kind == AuditKind.ScriptLog) + .Select(e => ScriptTraceExtra.TryParse(Row(e).Extra)!) + .ToList(); + Assert.Equal(3, logs.Count); + Assert.Equal(write.EventId, logs[0].StepEventId); + Assert.Equal(wait.EventId, logs[1].StepEventId); + Assert.Null(logs[2].StepEventId); + Assert.Equal(["runtime", "runtime", "script"], logs.Select(l => l.LogSource)); + } } diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs index 806e53c8..657fb1ec 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs @@ -156,6 +156,27 @@ public class TraceCapturingLoggerTests Assert.Throws(() => new TraceCapturingLogger(new RecordingLogger(), null!)); } + [Fact] + public void AThrowingFormatter_IsSwallowed_AndDropsOnlyThatLine() + { + // Review M3. Most of what this decorator captures is the runtime's own best-effort + // "audit write failed" warnings, logged from INSIDE a catch block: a formatter exception + // escaping here would replace the original failure with a formatting one on a path whose + // contract is that it never throws. The inner logger is disabled for this level so the + // decorator's OWN formatter call is the only one under test. + var (logger, inner, rows) = Make(innerMinimum: LogLevel.Critical); + + logger.Log(LogLevel.Warning, new EventId(0), "state", null, + (_, _) => throw new InvalidOperationException("formatter broke")); + + Assert.Empty(rows); + Assert.Empty(inner.Entries); + + // …and the decorator keeps working for the next line. + logger.LogWarning("still alive"); + Assert.Equal("still alive", Assert.Single(rows).Message); + } + [Fact] public void BeginScope_DelegatesToTheInnerLogger() {