fix(site-runtime): step-log review — trace-flag-gated ES step scope, shared-script Log, formatter guard

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.
2026-09-09 12:10:17 -04:00
parent 488d955ba2
commit ee8a8e9d3d
4 changed files with 209 additions and 11 deletions
@@ -237,6 +237,14 @@ public class ScriptRuntimeContext
    ///
    /// <para>Bounded per run (D7) and never throws into the script — see
    /// <see cref="ScriptLogger"/>.</para>
+    ///
+    /// <para><b>An inline shared script SHARES its caller's logger</b> (design §5): a context built
+    /// by <see cref="CreateChildContextForSharedScript"/> 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 <c>ExecutionId</c> and therefore land on the parent's <c>ScriptRun</c> node in
+    /// the Flow Debugger — not on the shared script's own execution node, even though its
+    /// <c>ApiCall</c>/<c>DbWrite</c>/step rows still chain under their own execution.</para>
    /// </summary>
    public ScriptLogger Log { get; }

@@ -296,6 +304,12 @@ public class ScriptRuntimeContext
    /// — mirrors <c>SiteRuntimeOptions.MaxLogLinesPerRun</c>, 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.
    /// </param>
+    /// <param name="sharedLog">
+    /// Step logs (design §5): an existing <see cref="ScriptLogger"/> to adopt as <see cref="Log"/>
+    /// instead of creating one — supplied only by
+    /// <see cref="CreateChildContextForSharedScript"/>, so an inline shared script shares its
+    /// caller's line cap and anchor. Null (the default) creates this run's own logger.
+    /// </param>
    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);
    }

    /// <summary>
@@ -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);

    /// <summary>
    /// Provides access to database operations.
@@ -1317,6 +1340,15 @@ public class ScriptRuntimeContext
        /// </summary>
        private readonly Action<AuditEvent>? _traceSink;

+        /// <summary>
+        /// Step logs (design 2026-09-09 D6): whether the owning run is traced. The authority for
+        /// opening a <see cref="TraceStepScope"/> around <see cref="Call"/>. Deliberately NOT
+        /// <see cref="_traceSink"/>: 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 <c>ScriptLog</c> rows that must name their step.
+        /// </summary>
+        private readonly bool _isTraced;
+
        /// <summary>
        /// Initializes a new external system helper for script API calls.
        /// </summary>
@@ -1331,6 +1363,7 @@ public class ScriptRuntimeContext
        /// <param name="parentExecutionId">Optional identifier of the parent execution (for routed calls).</param>
        /// <param name="sourceNode">Optional cluster node identifier (node-a/node-b) for audit stamping.</param>
        /// <param name="traceSink">Flow Debugger inline collector — receives the same <see cref="AuditEvent"/> each emit hands to the writer/forwarder; null when untraced.</param>
+        /// <param name="isTraced">Step logs (design D6): true when the owning run is traced, so <see cref="Call"/> pre-mints its row id and publishes it as the ambient step. Defaults to false for direct (test) construction.</param>
        // 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<AuditEvent>? traceSink = null)
+            Action<AuditEvent>? 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;
        }

        /// <summary>
@@ -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;
@@ -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);
    }
 }
@@ -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);
    }
+
+    /// <summary>
+    /// Review I1: the sync <c>ExternalSystem.Call</c> pre-mints its <c>ApiCall</c> 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.
+    /// </summary>
+    [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);
+    }
+
+    /// <summary>
+    /// 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 <c>ScriptLog</c> rows that
+    /// have to name their step.
+    /// </summary>
+    [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);
+    }
+
+    /// <summary>
+    /// Review I2 (design §5): an inline shared script SHARES its caller's <see cref="ScriptLogger"/>
+    /// — one counter, one anchor. Its lines therefore carry the PARENT run's <c>ExecutionId</c> and
+    /// land on the parent's <c>ScriptRun</c> node, even though its own step rows chain under its own
+    /// execution.
+    /// </summary>
+    [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);
+    }
+
+    /// <summary>
+    /// 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.
+    /// </summary>
+    [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<string, string?> { ["Recipe"] = "R-17" },
+            "Trigger", "1", "Ack", "1", TimeSpan.FromSeconds(3));
+
+        var batchReq = probe.ExpectMsg<WriteAttributeBatchRequest>(TimeSpan.FromSeconds(5));
+        probe.Reply(new WriteAttributeBatchResponse(batchReq.CorrelationId, true, null));
+        var waitReq = probe.ExpectMsg<WaitForAttributeRequest>(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));
+    }
 }
@@ -156,6 +156,27 @@ public class TraceCapturingLoggerTests
        Assert.Throws<ArgumentNullException>(() => 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()
    {