feat(site-runtime): Log global on ScriptRuntimeContext/ScriptGlobals; runtime lines attributed by TraceStepScope (D4-D6)

2026-09-09 11:53:06 -04:00
parent 9d9bb70a15
commit 488d955ba2
3 changed files with 368 additions and 16 deletions
@@ -145,7 +145,8 @@ public class ScriptRuntimeContextTraceEmissionTests : TestKit
        IExternalSystemClient? externalSystemClient = null,
        IDatabaseGateway? databaseGateway = null,
        ICachedCallTelemetryForwarder? cachedForwarder = null,
-        StoreAndForwardService? storeAndForward = null)
+        StoreAndForwardService? storeAndForward = null,
+        int maxLogLinesPerRun = 200)
        => new(
            instanceActor, NewLibrary(),
            currentCallDepth: 0, maxCallDepth: 10, askTimeout: TimeSpan.FromSeconds(5),
@@ -155,7 +156,8 @@ public class ScriptRuntimeContextTraceEmissionTests : TestKit
            siteId: "site-a", sourceScript: "ScriptActor:A", auditWriter: writer,
            cachedForwarder: cachedForwarder,
            executionId: executionId, parentExecutionId: parentExecutionId, sourceNode: "node-a",
-            isTraced: traced, traceCollector: collector);
+            isTraced: traced, traceCollector: collector,
+            maxLogLinesPerRun: maxLogLinesPerRun);

    [Fact]
    public async Task SetAttribute_WhenTraced_EmitsAttributeWriteRow_AndPassesTraceOnCommand()
@@ -556,4 +558,143 @@ public class ScriptRuntimeContextTraceEmissionTests : TestKit
        var written = Assert.Single(writer.Events);
        Assert.Equal(AuditKind.ApiCall, Row(written).Kind);
    }
+
+    // ---- Step logs: the Log global and runtime-line attribution (design 2026-09-09 D4-D7) ----
+
+    /// <summary>Fails every write so the context's own best-effort "write failed" warning fires —
+    /// the runtime line test (c) needs a genuine <c>_logger.LogWarning</c> inside a step body.</summary>
+    private sealed class ThrowingAuditWriter : IAuditWriter
+    {
+        public Task WriteAsync(AuditEvent evt, CancellationToken ct = default)
+            => throw new InvalidOperationException("writer down");
+    }
+
+    [Fact]
+    public void Log_WhenTraced_EmitsOneScriptLogRow_ToTheCollectorAndTheWriter()
+    {
+        var writer = new CapturingAuditWriter();
+        var collector = new FlowTraceCollector();
+        var ctx = CreateContext(CreateTestProbe().Ref, writer, traced: true, collector);
+
+        ctx.Log.Info("x");
+
+        var evt = Assert.Single(writer.Events);
+        Assert.Same(evt, Assert.Single(collector.Snapshot()));
+        var row = Row(evt);
+        Assert.Equal(AuditChannel.ScriptTrace, row.Channel);
+        Assert.Equal(AuditKind.ScriptLog, row.Kind);
+        Assert.Equal(AuditStatus.Delivered, row.Status);
+        Assert.Equal("x", row.RequestSummary);
+        Assert.Equal(ctx.ExecutionId, row.ExecutionId);
+        Assert.Equal("site-a", row.SourceSiteId);
+        Assert.Equal("node-a", evt.SourceNode);
+        Assert.Equal(InstanceName, row.SourceInstanceId);
+        // Same bare script name the ScriptRun anchor row carries, so the builder's fallback matches.
+        Assert.Equal("A", evt.Target);
+        var extra = ScriptTraceExtra.TryParse(row.Extra)!;
+        Assert.Equal("info", extra.LogLevel);
+        Assert.Equal("script", extra.LogSource);
+        Assert.Null(extra.StepEventId);
+        Assert.Equal(1, extra.Seq);
+    }
+
+    [Fact]
+    public void Log_WhenNotTraced_ReachesNeitherTheWriterNorTheCollector()
+    {
+        var writer = new CapturingAuditWriter();
+        var collector = new FlowTraceCollector();
+        var ctx = CreateContext(CreateTestProbe().Ref, writer, traced: false, collector);
+
+        ctx.Log.Info("x");
+        ctx.Log.Error("boom", new InvalidOperationException("e"));
+        ctx.Log.FlushDropped();
+
+        Assert.Empty(writer.Events);
+        Assert.Equal(0, collector.Count);
+        Assert.False(collector.LogsTruncated);
+    }
+
+    [Fact]
+    public async Task RuntimeWarning_InsideATracedWrite_IsAttributedToThatWriteStep()
+    {
+        var probe = CreateTestProbe();
+        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.
+        var ctx = CreateContext(probe.Ref, new ThrowingAuditWriter(), traced: true, collector);
+
+        var call = ctx.SetAttribute("Setpoint", "42");
+        var cmd = probe.ExpectMsg<SetStaticAttributeCommand>(TimeSpan.FromSeconds(5));
+        probe.Reply(new SetStaticAttributeResponse(cmd.CorrelationId, InstanceName, "Setpoint", true, null, DateTimeOffset.UtcNow));
+        await call;
+
+        var rows = collector.Snapshot();
+        var write = rows.Single(e => Row(e).Kind == AuditKind.AttributeWrite);
+        var log = rows.Single(e => Row(e).Kind == AuditKind.ScriptLog);
+        var extra = ScriptTraceExtra.TryParse(Row(log).Extra)!;
+        Assert.Equal("runtime", extra.LogSource);
+        Assert.Equal("warn", extra.LogLevel);
+        Assert.Equal(write.EventId, extra.StepEventId);
+    }
+
+    [Fact]
+    public void Log_WithException_CarriesTheMessageAndTheFullDetail()
+    {
+        var writer = new CapturingAuditWriter();
+        var ctx = CreateContext(CreateTestProbe().Ref, writer, traced: true, new FlowTraceCollector());
+
+        ctx.Log.Warn("m", new InvalidOperationException("e"));
+
+        var row = Row(Assert.Single(writer.Events));
+        Assert.Equal("m", row.RequestSummary);
+        Assert.Equal("e", row.ErrorMessage);
+        Assert.StartsWith("System.InvalidOperationException", row.ErrorDetail);
+        Assert.Equal("warn", ScriptTraceExtra.TryParse(row.Extra)!.LogLevel);
+    }
+
+    [Fact]
+    public async Task LogRows_RideTheLowPriorityLane_SoStepRowsKeepTheirReserve()
+    {
+        var probe = CreateTestProbe();
+        var writer = new CapturingAuditWriter();
+        // Reserve (50) + 1 => exactly one low-priority slot, while step rows keep the full cap.
+        var collector = new FlowTraceCollector(maxEvents: FlowTraceCollector.LowPriorityReserveEvents + 1);
+        var ctx = CreateContext(probe.Ref, writer, traced: true, collector);
+
+        ctx.Log.Info("first");
+        ctx.Log.Info("second");
+
+        Assert.Single(collector.Snapshot());
+        Assert.True(collector.LogsTruncated);
+        Assert.False(collector.Truncated);
+
+        var call = ctx.SetAttribute("Setpoint", "42");
+        var cmd = probe.ExpectMsg<SetStaticAttributeCommand>(TimeSpan.FromSeconds(5));
+        probe.Reply(new SetStaticAttributeResponse(cmd.CorrelationId, InstanceName, "Setpoint", true, null, DateTimeOffset.UtcNow));
+        await call;
+
+        Assert.Equal(2, collector.Count);
+        Assert.Contains(collector.Snapshot(), e => Row(e).Kind == AuditKind.AttributeWrite);
+    }
+
+    [Fact]
+    public void FlushDropped_EmitsTheClosingRow_OnceThePerRunCapIsExceeded()
+    {
+        var writer = new CapturingAuditWriter();
+        var collector = new FlowTraceCollector();
+        var ctx = CreateContext(CreateTestProbe().Ref, writer, traced: true, collector, maxLogLinesPerRun: 2);
+
+        ctx.Log.Info("1");
+        ctx.Log.Info("2");
+        ctx.Log.Info("3");
+        ctx.Log.FlushDropped();
+
+        var rows = collector.Snapshot();
+        Assert.Equal(3, rows.Count);
+        var closing = Row(rows[^1]);
+        var extra = ScriptTraceExtra.TryParse(closing.Extra)!;
+        Assert.Equal("warn", extra.LogLevel);
+        Assert.Equal("runtime", extra.LogSource);
+        Assert.Contains("1 line(s) dropped", closing.RequestSummary);
+    }
 }