diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptCompilationService.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptCompilationService.cs index d9a7e73d..fdc13e20 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptCompilationService.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptCompilationService.cs @@ -344,6 +344,9 @@ public class ScriptGlobals /// public AlarmsAccessor Alarms => Instance.Alarms; + /// Leveled per-run logging (design 2026-09-09). Usage: Log.Info("…"), Log.Warn("…", ex). Always reaches the node log; becomes Flow Debugger trace rows only for a traced run. + public ScriptLogger Log => Instance.Log; + /// /// Parent composition (null when this script is on a root-level template). /// Parent.Attributes["SpeedRPM"] reaches the parent's attribute; diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs index ea9f4a8b..84ddf4da 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs @@ -45,7 +45,24 @@ public class ScriptRuntimeContext private readonly int _currentCallDepth; private readonly int _maxCallDepth; private readonly TimeSpan _askTimeout; - private readonly ILogger _logger; + + /// + /// The logger every runtime diagnostic in this context goes through. NOT readonly because a + /// TRACED run swaps in a in the constructor (step-logs + /// design 2026-09-09 D6), so the warnings the runtime logs on the script's behalf become + /// ScriptLog rows attributed to the step that was running. An untraced run keeps the + /// injected logger untouched — no decorator, no allocation. + /// + private ILogger _logger; + + /// + /// The UNDECORATED injected logger. Every diagnostic emitted from inside the log path itself + /// () must use this one: routing it through would be + /// captured by the decorator and re-enter in a loop. Also the logger a + /// child (inline shared-script) context is built with, since + /// refuses to wrap itself. + /// + private readonly ILogger _innerLogger; private readonly string _instanceName; /// @@ -189,6 +206,40 @@ public class ScriptRuntimeContext /// private readonly Action? _traceSink; + /// + /// Step logs (design 2026-09-09 D7): the per-run ScriptLog row cap this context's + /// enforces, carried over verbatim into an inline shared-script child. + /// + private readonly int _maxLogLinesPerRun; + + /// + /// Step logs (design D4): the bare script name a ScriptLog row targets — the SAME value + /// the run's ScriptRun anchor row uses, so the Flow Debugger's anchor fallback lines up. + /// Derived from _sourceScript by dropping its ScriptActor: / AlarmActor: + /// prefix; the instance name when no script owns the context. + /// + private readonly string _logTarget; + + /// + /// Step logs (design D4): per-run emission counter stamped on every ScriptLog row as + /// ScriptTraceExtra.Seq, so lines produced inside the same millisecond still sort. + /// + private int _logSeq; + + /// + /// Step logs (design 2026-09-09 D4/D5): the Log global site scripts call — + /// Log.Debug/Info/Warn/Error(message, exception?). + /// + /// Every line ALWAYS reaches the node's , traced or not. A + /// ScriptLog trace row is additionally produced only when this run is traced: an + /// untraced context builds the logger with a null emitter, so the row path is one null check + /// and the untraced run is byte-identical to the pre-feature behaviour. + /// + /// Bounded per run (D7) and never throws into the script — see + /// . + /// + public ScriptLogger Log { get; } + /// /// Initializes a new script runtime context with all dependencies for script /// execution, external system calls, database access, and notification delivery. @@ -240,6 +291,11 @@ public class ScriptRuntimeContext /// /// Flow Debugger trace flag — see design 2026-09-05 §5.2. Defaults to untraced. /// Flow Debugger per-run inline trace sink (design §5.4); null when untraced. + /// + /// Step logs (design 2026-09-09 D7): the per-run ScriptLog row cap for + /// — 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. + /// public ScriptRuntimeContext( IActorRef instanceActor, SharedScriptLibrary sharedScriptLibrary, @@ -263,7 +319,8 @@ public class ScriptRuntimeContext ISiteEventLogger? siteEventLogger = null, CancellationToken scriptTimeoutToken = default, bool isTraced = false, - FlowTraceCollector? traceCollector = null) + FlowTraceCollector? traceCollector = null, + int maxLogLinesPerRun = 200) { _instanceActor = instanceActor; _sharedScriptLibrary = sharedScriptLibrary; @@ -271,6 +328,7 @@ public class ScriptRuntimeContext _maxCallDepth = maxCallDepth; _askTimeout = askTimeout; _instanceName = instanceName; + _innerLogger = logger; _logger = logger; _externalSystemClient = externalSystemClient; _databaseGateway = databaseGateway; @@ -298,6 +356,24 @@ public class ScriptRuntimeContext _isTraced = isTraced; _traceCollector = traceCollector; _traceSink = traceCollector is null ? null : Collect; + + // Step logs (design 2026-09-09 D4-D6). ORDER MATTERS: the Log global is built over the + // UNDECORATED logger first, and only then — when traced — does the context's own logger + // become the capturing decorator over that same sink. Building them the other way round + // would hand ScriptLogger the decorator (every Log.* line logged, captured and re-emitted + // as a second row) and TraceCapturingLogger refuses to wrap itself for exactly that reason. + _maxLogLinesPerRun = Math.Max(1, maxLogLinesPerRun); + _logTarget = string.IsNullOrEmpty(_sourceScript) + // No single script owns the context — the instance is the closest honest target. + ? _instanceName + // "ScriptActor:Foo" / "AlarmActor:Foo" -> "Foo"; a bare name is unchanged (IndexOf -1). + : _sourceScript[(_sourceScript.IndexOf(':') + 1)..]; + Log = new ScriptLogger( + logger, isTraced ? EmitLog : null, _maxLogLinesPerRun, _instanceName, _logTarget, _executionId); + if (isTraced) + { + _logger = new TraceCapturingLogger(logger, Log); + } } /// @@ -378,7 +454,9 @@ public class ScriptRuntimeContext _maxCallDepth, _askTimeout, _instanceName, - _logger, + // Step logs (D6): the UNDECORATED logger — the child installs its own capturing + // decorator when traced, and TraceCapturingLogger refuses to wrap another one. + _innerLogger, _externalSystemClient, _databaseGateway, _storeAndForward, @@ -401,7 +479,10 @@ public class ScriptRuntimeContext // Flow Debugger (design §5.2): a traced root traces its whole tree — the inline // shared script shares the same flag AND the same inline sink. isTraced: _isTraced, - traceCollector: _traceCollector); + 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); } /// @@ -411,9 +492,22 @@ public class ScriptRuntimeContext /// throws into the script, and hands raw payloads to the writer whose redactor applies /// the configured size cap (§9) exactly as the other channels do. /// + /// The trace row's kind. + /// The row's lifecycle status. + /// The row's target (attribute name, script name, …). + /// When the traced action started — the row's OccurredAtUtc. + /// How long the action took. + /// Request summary. + /// Response summary. + /// Error message on a failed row. + /// Kind-specific extra detail. + /// + /// Step logs (design 2026-09-09 D6): the step's PRE-MINTED EventId, so the log lines the + /// runtime produced inside the step's can name it. Null mints one. + /// private void EmitTrace( AuditKind kind, AuditStatus status, string target, DateTime startedUtc, int durationMs, - string? input, string? output, string? error, ScriptTraceExtra? extra) + string? input, string? output, string? error, ScriptTraceExtra? extra, Guid? eventId = null) { if (!_isTraced) return; AuditEvent evt; @@ -421,6 +515,7 @@ public class ScriptRuntimeContext { evt = ScadaBridgeAuditEventFactory.Create( AuditChannel.ScriptTrace, kind, status, + eventId: eventId, occurredAtUtc: DateTime.SpecifyKind(startedUtc, DateTimeKind.Utc), actor: _sourceScript, target: target, sourceNode: _sourceNode, executionId: _executionId, parentExecutionId: _parentExecutionId, @@ -456,6 +551,79 @@ public class ScriptRuntimeContext } } + /// + /// Step logs (design 2026-09-09 D4/D7): emits one ScriptTrace/ScriptLog row for a + /// single log line — the collector's LOW-PRIORITY lane first (log lines must never crowd out + /// the step rows a run emits at its end), then the best-effort . + /// + /// This is the emitter handed to , and it is wired only when the run is + /// traced. Every diagnostic it logs itself goes to , NEVER to + /// : on a traced run the latter is the capturing decorator, which would + /// feed the warning straight back into this method. + /// + /// Level name as it appears on the wire: debug|info|warn|error. + /// Line origin: script (a Log.* call) or runtime. + /// The already-clipped message text. + /// The exception attached to the line, if any. + /// The owning step's EventId; null falls back to the run's anchor row (D2). + private void EmitLog(string level, string source, string message, Exception? exception, Guid? stepEventId) + { + if (!_isTraced) return; + AuditEvent evt; + try + { + evt = ScadaBridgeAuditEventFactory.Create( + AuditChannel.ScriptTrace, AuditKind.ScriptLog, AuditStatus.Delivered, + occurredAtUtc: DateTime.UtcNow, + actor: _sourceScript, target: _logTarget, sourceNode: _sourceNode, + executionId: _executionId, parentExecutionId: _parentExecutionId, + sourceSiteId: string.IsNullOrEmpty(_siteId) ? null : _siteId, + sourceInstanceId: _instanceName, sourceScript: _sourceScript, + errorMessage: exception?.Message, errorDetail: exception?.ToString(), + requestSummary: message, + extra: new ScriptTraceExtra + { + LogLevel = level, + LogSource = source, + StepEventId = stepEventId, + Seq = Interlocked.Increment(ref _logSeq), + }.ToJson()); + } + catch (Exception ex) + { + _innerLogger.LogWarning(ex, "Flow trace log-line build failed at {Level}", level); + return; + } + + try + { + // Low-priority lane (D7): dropped lines set LogsTruncated, not Truncated. + _traceCollector?.Add(evt, lowPriority: true); + } + catch (Exception ex) + { + _innerLogger.LogWarning(ex, "Flow trace collector rejected log line ({EventId})", evt.EventId); + } + + if (_auditWriter is null) return; + try + { + var t = _auditWriter.WriteAsync(evt, CancellationToken.None); + if (!t.IsCompletedSuccessfully) + { + _ = t.ContinueWith( + x => _innerLogger.LogWarning(x.Exception, "Flow trace log-line write failed ({EventId})", evt.EventId), + CancellationToken.None, + TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously, + TaskScheduler.Default); + } + } + catch (Exception ex) + { + _innerLogger.LogWarning(ex, "Flow trace log-line write failed ({EventId})", evt.EventId); + } + } + /// Serialises a small trace payload; null on failure (best-effort, like the audit helpers). private static string? TraceJson(object? value) { @@ -618,6 +786,11 @@ public class ScriptRuntimeContext var startedUtc = DateTime.UtcNow; var sw = _isTraced ? Stopwatch.StartNew() : null; + // Step logs (design D6): pre-mint this step's row id and make it the ambient step for the + // body, so a warning the runtime logs while the wait is in flight names THIS row. Nothing + // is minted and no scope is opened on an untraced run. + Guid? stepId = _isTraced ? Guid.NewGuid() : null; + using var step = stepId is { } waitStepId ? TraceStepScope.Enter(waitStepId) : null; WaitForAttributeResponse response; try { @@ -648,7 +821,8 @@ public class ScriptRuntimeContext { WaitAttribute = name, WaitTarget = targetValueEncoded ?? (predicate is null ? null : ""), WaitTimeoutMs = (int)timeout.TotalMilliseconds, WaitOutcome = "cancelled", - }); + }, + eventId: stepId); } throw; } @@ -670,7 +844,8 @@ public class ScriptRuntimeContext WaitTimeoutMs = (int)timeout.TotalMilliseconds, WaitOutcome = outcome, ObservedValue = observed, - }); + }, + eventId: stepId); } return response; @@ -706,6 +881,10 @@ public class ScriptRuntimeContext var startedUtc = DateTime.UtcNow; var sw = _isTraced ? Stopwatch.StartNew() : null; + // Step logs (design D6): one pre-minted row id shared by BOTH emit points below, opened as + // the ambient step so runtime warnings logged during the write are attributed to it. + Guid? stepId = _isTraced ? Guid.NewGuid() : null; + using var step = stepId is { } writeStepId ? TraceStepScope.Enter(writeStepId) : null; SetStaticAttributeResponse response; try { @@ -717,7 +896,8 @@ public class ScriptRuntimeContext { EmitTrace(AuditKind.AttributeWrite, AuditStatus.Failed, attributeName, startedUtc, (int)sw.ElapsedMilliseconds, TraceJson(new { attribute = attributeName, value }), null, ex.Message, - new ScriptTraceExtra { Writes = [new AttributeWriteDetail(attributeName, value, false, ex.Message)] }); + new ScriptTraceExtra { Writes = [new AttributeWriteDetail(attributeName, value, false, ex.Message)] }, + eventId: stepId); throw; } @@ -732,7 +912,8 @@ public class ScriptRuntimeContext extra: new ScriptTraceExtra { Writes = [new AttributeWriteDetail(attributeName, value, response.Success, response.ErrorMessage)], - }); + }, + eventId: stepId); } if (!response.Success) @@ -772,6 +953,10 @@ public class ScriptRuntimeContext // than an AskTimeoutException here. Honors the script execution-timeout token. var startedUtc = DateTime.UtcNow; var sw = _isTraced ? Stopwatch.StartNew() : null; + // Step logs (design D6): the batch's own step. The trailing WaitAttribute opens its own + // nested scope and restores this one on the way out, so each leg owns its lines. + Guid? stepId = _isTraced ? Guid.NewGuid() : null; + using var step = stepId is { } batchStepId ? TraceStepScope.Enter(batchStepId) : null; var batchResp = await _instanceActor.Ask( batchReq, TimeSpan.FromSeconds(35), _scriptTimeoutToken); @@ -789,7 +974,8 @@ public class ScriptRuntimeContext input: TraceJson(new { values = encodedValues, trigger = triggerAttr, triggerValue = triggerEncoded }), output: null, error: batchResp.ErrorMessage, - extra: new ScriptTraceExtra { TriggerAttribute = triggerAttr, TriggerValue = triggerEncoded, Writes = writes }); + extra: new ScriptTraceExtra { TriggerAttribute = triggerAttr, TriggerValue = triggerEncoded, Writes = writes }, + eventId: stepId); } if (!batchResp.Success) @@ -1207,6 +1393,12 @@ public class ScriptRuntimeContext // audit emission is best-effort. var occurredAtUtc = DateTime.UtcNow; 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; + using var step = stepId is { } callStepId ? TraceStepScope.Enter(callStepId) : null; ExternalCallResult? result = null; Exception? thrown = null; try @@ -1223,7 +1415,7 @@ public class ScriptRuntimeContext { var elapsedMs = (int)((Stopwatch.GetTimestamp() - startTicks) * 1000d / Stopwatch.Frequency); - EmitCallAudit(systemName, methodName, occurredAtUtc, elapsedMs, result, thrown, parameters); + EmitCallAudit(systemName, methodName, occurredAtUtc, elapsedMs, result, thrown, parameters, stepId); } } @@ -1610,6 +1802,18 @@ public class ScriptRuntimeContext /// row. Any exception thrown by the writer is logged and swallowed — /// audit-write failures must never abort the user-facing action. /// + /// External system name. + /// Method invoked on it. + /// When the call started. + /// How long it took. + /// The call result, when one was produced. + /// The exception the call threw, if any. + /// The call arguments. + /// + /// Step logs (design 2026-09-09 D6): the PRE-MINTED row id also opened as + /// the ambient , so the log lines produced during the call name + /// this row. Null (untraced) mints a fresh id as before. + /// private void EmitCallAudit( string systemName, string methodName, @@ -1617,7 +1821,8 @@ public class ScriptRuntimeContext int durationMs, ExternalCallResult? result, Exception? thrown, - IReadOnlyDictionary? parameters) + IReadOnlyDictionary? parameters, + Guid? eventId = null) { if (_auditWriter == null) { @@ -1628,7 +1833,7 @@ public class ScriptRuntimeContext try { evt = BuildCallAuditEvent( - systemName, methodName, occurredAtUtc, durationMs, result, thrown, parameters); + systemName, methodName, occurredAtUtc, durationMs, result, thrown, parameters, eventId); } catch (Exception buildEx) { @@ -1687,7 +1892,8 @@ public class ScriptRuntimeContext int durationMs, ExternalCallResult? result, Exception? thrown, - IReadOnlyDictionary? parameters) + IReadOnlyDictionary? parameters, + Guid? eventId = null) { // Status: Delivered on a Success result; Failed otherwise (the // ExternalSystemClient already maps HTTP non-2xx + transient @@ -1728,6 +1934,8 @@ public class ScriptRuntimeContext channel: AuditChannel.ApiOutbound, kind: AuditKind.ApiCall, status: status, + // Step logs (D6): the id the caller already published as the ambient step. + eventId: eventId, occurredAtUtc: DateTime.SpecifyKind(occurredAtUtc, DateTimeKind.Utc), // Outbound channel: per the Audit Log Actor-column spec the actor // is the calling script. Null when no single script owns the call 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 267e6a70..917a717b 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRuntimeContextTraceEmissionTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRuntimeContextTraceEmissionTests.cs @@ -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) ---- + + /// Fails every write so the context's own best-effort "write failed" warning fires — + /// the runtime line test (c) needs a genuine _logger.LogWarning inside a step body. + 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(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(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); + } }