Merge wt/step-logs-t5: Task 5 Log global wired into ScriptRuntimeContext
This commit is contained in:
Joseph Doherty
+268
-2
@@ -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,268 @@ 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.
|
||||
//
|
||||
// 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");
|
||||
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);
|
||||
}
|
||||
|
||||
/// <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()
|
||||
{
|
||||
|
||||
Reference in New Issue
Block a user