diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptLogger.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptLogger.cs new file mode 100644 index 00000000..e2a44bd4 --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptLogger.cs @@ -0,0 +1,192 @@ +using Microsoft.Extensions.Logging; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +/// +/// The row-emitting callback a uses: level name, source, message, +/// optional exception, owning step id (design 2026-09-09 D1/D2). +/// +/// Level name as it appears on the wire: debug|info|warn|error. +/// Line origin: script (the author's own Log.* call) or runtime. +/// The already-clipped message text. +/// The exception attached to the line, if any. +/// The step row the line belongs to, or to fall back to the run's anchor row. +public delegate void ScriptLogEmitter(string level, string source, string message, Exception? exception, Guid? stepEventId); + +/// +/// Flow Debugger step logs (design 2026-09-09 D4/D5/D7): the Log global site scripts call. +/// +/// Every line ALWAYS forwards to the node's — an untraced run is a +/// normal logging surface and pays nothing else. A ScriptLog audit row is emitted only +/// when the run is traced, i.e. only when the owning ScriptRuntimeContext supplied an +/// emitter; untraced runs construct the logger with a emitter and the row +/// path is a single null check. +/// +/// Bounded (D7). At most maxLines rows per run — one +/// instance is one run's counter, and inline shared scripts share the context, hence the counter — +/// plus a hard cap per message. Lines past the cap are counted and +/// dropped; emits the single closing warning that names the count. +/// +/// Never throws into the script. A logging or emitting failure is swallowed: this is a +/// debug observer, and a broken observer must not fail a production script run. +/// +public sealed class ScriptLogger +{ + /// Per-message character cap (design D7); longer messages are truncated and suffixed with an ellipsis. + public const int MaxMessageChars = 2_000; + + private readonly ILogger _logger; + private readonly ScriptLogEmitter? _emit; + private readonly int _maxLines; + private readonly string _instance; + private readonly string _script; + private readonly Guid? _executionId; + + private int _emitted; + private int _dropped; + + /// Creates the Log global for one script run. + /// The node logger every line forwards to, traced or not. + /// Row emitter; when the run is not traced (no rows are produced). + /// Per-run row cap (design D7); must be greater than zero. + /// Instance unique name, for the structured log entry. + /// Script name, for the structured log entry. + /// The run's execution id, for the structured log entry. + /// is null. + /// is not greater than zero. + public ScriptLogger(ILogger logger, ScriptLogEmitter? emit, int maxLines, string instance, string script, Guid? executionId) + { + ArgumentNullException.ThrowIfNull(logger); + ArgumentOutOfRangeException.ThrowIfLessThan(maxLines, 1); + + _logger = logger; + _emit = emit; + _maxLines = maxLines; + _instance = instance; + _script = script; + _executionId = executionId; + } + + /// Logs a diagnostic line at Debug level. + /// The message text (clipped at ). + /// An optional exception to attach to the line. + public void Debug(string message, Exception? exception = null) => Write(LogLevel.Debug, "debug", message, exception); + + /// Logs an informational line. + /// The message text (clipped at ). + /// An optional exception to attach to the line. + public void Info(string message, Exception? exception = null) => Write(LogLevel.Information, "info", message, exception); + + /// Logs a warning line. + /// The message text (clipped at ). + /// An optional exception to attach to the line. + public void Warn(string message, Exception? exception = null) => Write(LogLevel.Warning, "warn", message, exception); + + /// Logs an error line. Does not fail the run — the script decides what to do next. + /// The message text (clipped at ). + /// An optional exception to attach to the line. + public void Error(string message, Exception? exception = null) => Write(LogLevel.Error, "error", message, exception); + + /// + /// Runtime-sourced line (fed by ); same caps, source + /// runtime; does NOT forward to the — the caller already logged it, + /// and re-logging would loop back through the decorator. + /// + /// Level name (info|warn|error). + /// The already-formatted message text. + /// The exception attached to the entry, if any. + internal void Runtime(string level, string message, Exception? exception) => WriteRow(level, "runtime", message, exception); + + /// Forwards to the node logger, then records the trace row (when traced). + private void Write(LogLevel level, string name, string message, Exception? exception) + { + message = Clip(message); + try + { + _logger.Log(level, exception, "[script] {Instance}/{Script} {ExecutionId}: {Message}", _instance, _script, _executionId, message); + } + catch + { + // Deliberate swallow: a failing logger sink must never propagate into the script body. + } + + WriteRow(name, "script", message, exception); + } + + /// Emits one trace row, subject to the per-run line cap. + private void WriteRow(string level, string source, string message, Exception? exception) + { + if (_emit is null) + { + return; // Untraced run: no rows, no counting. + } + + if (Interlocked.Increment(ref _emitted) > _maxLines) + { + Interlocked.Increment(ref _dropped); + return; + } + + try + { + _emit(level, source, Clip(message), exception, TraceStepScope.Current); + } + catch + { + // Deliberate swallow: the trace collector/audit writer is a debug observer, never a run failure. + } + } + + /// + /// Run end: emits one closing warning naming the dropped count (nothing when none were + /// dropped). Bypasses the counter on purpose — it is the one row that must always land. + /// Idempotent: the count is cleared as it is reported, so a second call emits nothing. + /// + public void FlushDropped() + { + if (_emit is null) + { + return; + } + + var n = Interlocked.Exchange(ref _dropped, 0); + if (n == 0) + { + return; + } + + try + { + _emit("warn", "runtime", $"Log truncated: {n} line(s) dropped past the per-run cap of {_maxLines}", null, null); + } + catch + { + // Deliberate swallow: same reason as WriteRow — the observer must not fail the run. + } + } + + /// + /// Applies the per-message cap, marking a truncated message with a trailing ellipsis. + /// + /// Cuts one char short when the cap would land between the two halves of a surrogate + /// pair, so an emoji straddling the boundary is dropped whole rather than leaving a lone + /// surrogate that breaks JSON serialization downstream. Re-clipping an already-clipped message + /// is a no-op, which matters because the script path clips once before logging and again + /// before emitting. + /// + private static string Clip(string? m) + { + if (m is null) + { + return string.Empty; + } + + if (m.Length <= MaxMessageChars) + { + return m; + } + + var keep = char.IsHighSurrogate(m[MaxMessageChars - 1]) ? MaxMessageChars - 1 : MaxMessageChars; + return m[..keep] + "…"; + } +} diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs new file mode 100644 index 00000000..ed71e6d0 --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs @@ -0,0 +1,79 @@ +using Microsoft.Extensions.Logging; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +/// +/// Flow Debugger step logs (design 2026-09-09 D6): decorates the script context's +/// while a run is traced. +/// +/// Forwards EVERYTHING to the inner logger unchanged (the node's log file is unaffected by +/// tracing), and additionally copies and above into +/// ScriptLog rows with source runtime, attributed to the ambient +/// . This is how the warnings the runtime logs on the script's behalf — +/// inside SetAttribute, WriteBatchAndWait, WaitInternal, the sync +/// ExternalSystem.Call — reach the Flow Debugger without editing each call site. +/// +/// Debug and Trace are deliberately NOT captured (internal chatter, design D6), and the +/// per-run line cap of the sink applies to what is. +/// +/// Installed only when the run is traced, so an untraced run keeps the bare inner logger. +/// +public sealed class TraceCapturingLogger : ILogger +{ + private readonly ILogger _inner; + private readonly ScriptLogger _sink; + + /// Wraps so that Information and above also reach . + /// The node logger every entry is forwarded to. + /// The run's , which owns the caps and the row emitter. + /// or is null. + /// is itself a . + public TraceCapturingLogger(ILogger inner, ScriptLogger sink) + { + ArgumentNullException.ThrowIfNull(inner); + ArgumentNullException.ThrowIfNull(sink); + if (inner is TraceCapturingLogger) + { + throw new ArgumentException("inner is already a TraceCapturingLogger — wrapping twice would emit two rows per script line", nameof(inner)); + } + + _inner = inner; + _sink = sink; + } + + /// + public IDisposable? BeginScope(TState state) where TState : notnull => _inner.BeginScope(state); + + /// + /// Information and above are always enabled — they are trace data even when the node's minimum + /// level is Warning. Below Information the inner logger decides. + /// + /// The level being tested. + /// when the entry should be produced. + public bool IsEnabled(LogLevel level) => level >= LogLevel.Information || _inner.IsEnabled(level); + + /// + public void Log(LogLevel level, EventId eventId, TState state, Exception? exception, Func formatter) + { + // Forward first, and only if the inner logger actually wants it: IsEnabled above lies + // upward for trace capture, so the node's own minimum level must be re-checked here. + if (_inner.IsEnabled(level)) + { + _inner.Log(level, eventId, state, exception, formatter); + } + + if (level < LogLevel.Information || level == LogLevel.None) + { + return; + } + + var name = level switch + { + LogLevel.Information => "info", + LogLevel.Warning => "warn", + _ => "error", + }; + + _sink.Runtime(name, formatter(state, exception), exception); + } +} diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceStepScope.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceStepScope.cs new file mode 100644 index 00000000..09945bf2 --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceStepScope.cs @@ -0,0 +1,44 @@ +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +/// +/// Flow Debugger step logs (design 2026-09-09 D6): the ambient "which step is running right now" +/// marker used to attribute runtime-sourced log lines to a step node. +/// +/// A ScriptLog row names its owning step explicitly (D2), but the runtime lines the +/// node logs on the script's behalf are produced deep inside a helper — the helper knows its +/// pre-minted step EventId, the logging call site does not. Rather than thread that id +/// through every internal call, the helpers open a scope around their body and +/// reads when no explicit id is supplied. +/// +/// so the value flows through the helper's own awaits and +/// nowhere else: it is captured by continuations started inside the scope and is invisible to +/// concurrent runs on other threads of the script execution pool. Lines logged outside any scope +/// see and fall back to the execution's anchor row (D2). +/// +public static class TraceStepScope +{ + private static readonly AsyncLocal _current = new(); + + /// The step EventId owning the currently executing helper body, or outside any scope. + public static Guid? Current => _current.Value; + + /// + /// Sets the current step for the scope's lifetime; restores the previous value on dispose, + /// so nested scopes (a helper calling another helper) unwind correctly. + /// + /// The pre-minted EventId of the step row this body belongs to. + /// A handle that restores the previous ambient value when disposed. + public static IDisposable Enter(Guid stepEventId) + { + var prev = _current.Value; + _current.Value = stepEventId; + return new Restore(prev); + } + + /// Restores the ambient step id captured at time. + private sealed class Restore(Guid? prev) : IDisposable + { + /// + public void Dispose() => _current.Value = prev; + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptLoggerTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptLoggerTests.cs new file mode 100644 index 00000000..6c400c61 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptLoggerTests.cs @@ -0,0 +1,320 @@ +using Microsoft.Extensions.Logging; +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts; + +/// +/// Flow Debugger step logs (design 2026-09-09 D4/D5/D7): the Log global's two obligations — +/// ALWAYS forward to the node logger, emit a trace row ONLY when traced — plus the per-run line cap, +/// the per-message character cap, step attribution through , and the +/// "never throws into the script" rule. +/// +/// Deliberately built without a ScriptRuntimeContext: the row emitter is a delegate +/// precisely so this surface is testable on its own. +/// +public class ScriptLoggerTests +{ + /// One entry the logger under test forwarded to the node logger. + private sealed record LogEntry(LogLevel Level, string Message, Exception? Exception); + + /// A minimal recording — clearer here than a mocking framework. + private sealed class RecordingLogger(bool enabled = true) : ILogger + { + public List Entries { get; } = []; + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => enabled; + + public void Log(LogLevel level, EventId eventId, TState state, Exception? exception, Func formatter) => + Entries.Add(new LogEntry(level, formatter(state, exception), exception)); + } + + /// One row the logger under test handed to its emitter. + private sealed record Row(string Level, string Source, string Message, Exception? Exception, Guid? StepEventId); + + private static (ScriptLogger Logger, RecordingLogger Node, List Rows) MakeTraced(int maxLines = 200) + { + var node = new RecordingLogger(); + var rows = new List(); + var logger = new ScriptLogger( + node, + (level, source, message, exception, stepEventId) => rows.Add(new Row(level, source, message, exception, stepEventId)), + maxLines, + instance: "CvdReactor01", + script: "OnHeartbeat", + executionId: Guid.NewGuid()); + return (logger, node, rows); + } + + [Fact] + public void UntracedRun_ForwardsToTheNodeLogger_AndEmitsNoRow() + { + // D5: an untraced run is an ordinary logging surface — the author's messages are never lost, + // but nothing is audited. + var node = new RecordingLogger(); + var logger = new ScriptLogger(node, emit: null, maxLines: 200, "CvdReactor01", "OnHeartbeat", Guid.NewGuid()); + + logger.Info("hello"); + logger.Warn("careful"); + + Assert.Equal(2, node.Entries.Count); + Assert.Equal(LogLevel.Information, node.Entries[0].Level); + Assert.Contains("hello", node.Entries[0].Message); + Assert.Equal(LogLevel.Warning, node.Entries[1].Level); + } + + [Fact] + public void TracedRun_EmitsOneScriptSourcedRowPerLine() + { + var (logger, node, rows) = MakeTraced(); + + logger.Info("msg"); + + Assert.Single(node.Entries); + var row = Assert.Single(rows); + Assert.Equal(("info", "script", "msg", (Exception?)null, (Guid?)null), (row.Level, row.Source, row.Message, row.Exception, row.StepEventId)); + } + + [Fact] + public void EveryLevel_MapsToItsWireName() + { + var (logger, node, rows) = MakeTraced(); + + logger.Debug("d"); + logger.Info("i"); + logger.Warn("w"); + logger.Error("e"); + + Assert.Equal(["debug", "info", "warn", "error"], rows.Select(r => r.Level)); + Assert.Equal( + [LogLevel.Debug, LogLevel.Information, LogLevel.Warning, LogLevel.Error], + node.Entries.Select(e => e.Level)); + } + + [Fact] + public void LineInsideAStepScope_IsAttributedToThatStep_AndTheScopeUnwinds() + { + // D6: the ambient scope is how a line written inside a helper body names its step node. + var (logger, _, rows) = MakeTraced(); + var stepId = Guid.NewGuid(); + + using (TraceStepScope.Enter(stepId)) + { + Assert.Equal(stepId, TraceStepScope.Current); + logger.Info("inside"); + } + + Assert.Null(TraceStepScope.Current); + logger.Info("outside"); + + Assert.Equal(stepId, rows[0].StepEventId); + Assert.Null(rows[1].StepEventId); + } + + [Fact] + public void NestedStepScopes_Unwind_ToTheEnclosingStep() + { + // A helper calling another helper: the inner step owns its own lines, and the outer step + // gets its attribution back the moment the inner scope closes. + var (logger, _, rows) = MakeTraced(); + var outer = Guid.NewGuid(); + var inner = Guid.NewGuid(); + + using (TraceStepScope.Enter(outer)) + { + using (TraceStepScope.Enter(inner)) + { + Assert.Equal(inner, TraceStepScope.Current); + logger.Info("inner"); + } + + Assert.Equal(outer, TraceStepScope.Current); + logger.Info("outer"); + } + + Assert.Null(TraceStepScope.Current); + Assert.Equal(inner, rows[0].StepEventId); + Assert.Equal(outer, rows[1].StepEventId); + } + + [Fact] + public void PastThePerRunCap_LinesAreDropped_AndFlushDroppedNamesTheCount_Once() + { + // D7: bounded per run; the closing row bypasses the cap because it is the only signal that + // anything was lost — and it is idempotent so a double flush cannot duplicate it. + var (logger, _, rows) = MakeTraced(maxLines: 3); + + for (var i = 0; i < 5; i++) + { + logger.Info($"line {i}"); + } + + Assert.Equal(3, rows.Count); + Assert.Equal(["line 0", "line 1", "line 2"], rows.Select(r => r.Message)); + + logger.FlushDropped(); + + Assert.Equal(4, rows.Count); + var closing = rows[^1]; + Assert.Equal("warn", closing.Level); + Assert.Equal("runtime", closing.Source); + Assert.Contains("2 line(s)", closing.Message); + Assert.Null(closing.StepEventId); + + logger.FlushDropped(); + + Assert.Equal(4, rows.Count); + } + + [Fact] + public void FlushDropped_EmitsNothing_WhenNoLineWasDropped() + { + var (logger, _, rows) = MakeTraced(maxLines: 3); + + logger.Info("only one"); + logger.FlushDropped(); + + Assert.Single(rows); + } + + [Fact] + public void MessagesLongerThanTheCap_AreClippedWithAnEllipsis() + { + var (logger, _, rows) = MakeTraced(); + + logger.Info(new string('x', 2_500)); + + var message = Assert.Single(rows).Message; + Assert.Equal(ScriptLogger.MaxMessageChars + 1, message.Length); + Assert.EndsWith("…", message); + } + + [Fact] + public void AMessageExactlyAtTheCap_PassesThroughUnclipped() + { + var (logger, _, rows) = MakeTraced(); + var exact = new string('x', ScriptLogger.MaxMessageChars); + + logger.Info(exact); + + Assert.Equal(exact, Assert.Single(rows).Message); + } + + [Fact] + public void ASurrogatePairStraddlingTheCap_IsDroppedWhole() + { + // Cutting between the halves would leave a lone surrogate, which breaks JSON serialization + // of the audit row further down the pipe. + var (logger, _, rows) = MakeTraced(); + var straddling = new string('x', ScriptLogger.MaxMessageChars - 1) + "🚀" + new string('y', 10); + + logger.Info(straddling); + + var message = Assert.Single(rows).Message; + Assert.Equal(ScriptLogger.MaxMessageChars, message.Length); + Assert.EndsWith("…", message); + Assert.DoesNotContain(message, static c => char.IsSurrogate(c)); + } + + [Fact] + public void AThrowingEmitter_NeverReachesTheScript_AndTheNodeLoggerStillGotTheLine() + { + // The whole feature is a debug observer: a broken observer must not fail a production run. + var node = new RecordingLogger(); + var logger = new ScriptLogger( + node, + (_, _, _, _, _) => throw new InvalidOperationException("collector is broken"), + maxLines: 200, + "CvdReactor01", + "OnHeartbeat", + Guid.NewGuid()); + + logger.Info("still logged"); + + Assert.Single(node.Entries); + Assert.Contains("still logged", node.Entries[0].Message); + } + + [Fact] + public void AThrowingNodeLogger_NeverReachesTheScript_AndTheRowIsStillEmitted() + { + var rows = new List(); + var logger = new ScriptLogger( + new ThrowingLogger(), + (level, source, message, exception, stepEventId) => rows.Add(new Row(level, source, message, exception, stepEventId)), + maxLines: 200, + "CvdReactor01", + "OnHeartbeat", + Guid.NewGuid()); + + logger.Warn("sink is down"); + + Assert.Single(rows); + } + + /// A node logger whose sink fails, standing in for a wedged Serilog sink. + private sealed class ThrowingLogger : ILogger + { + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel level, EventId eventId, TState state, Exception? exception, Func formatter) => + throw new InvalidOperationException("sink is down"); + } + + [Fact] + public void AnAttachedException_ReachesBothTheNodeLoggerAndTheRow() + { + var (logger, node, rows) = MakeTraced(); + var boom = new InvalidOperationException("boom"); + + logger.Error("x", boom); + + Assert.Same(boom, node.Entries[0].Exception); + Assert.Same(boom, Assert.Single(rows).Exception); + } + + [Fact] + public void RuntimeLines_AreRowOnly_AndCarryTheRuntimeSource() + { + // The capturing logger has already written the entry to the node logger; re-logging it here + // would double it (and loop straight back through the decorator). + var (logger, node, rows) = MakeTraced(); + + logger.Runtime("warn", "tag write timed out", null); + + Assert.Empty(node.Entries); + var row = Assert.Single(rows); + Assert.Equal("warn", row.Level); + Assert.Equal("runtime", row.Source); + } + + [Fact] + public void RuntimeLines_ShareThePerRunCapWithScriptLines() + { + var (logger, _, rows) = MakeTraced(maxLines: 2); + + logger.Info("script line"); + logger.Runtime("info", "runtime line", null); + logger.Runtime("info", "dropped", null); + + Assert.Equal(2, rows.Count); + logger.FlushDropped(); + Assert.Contains("1 line(s)", rows[^1].Message); + } + + [Fact] + public void MaxLinesMustBePositive() + { + Assert.Throws(() => + new ScriptLogger(new RecordingLogger(), emit: null, maxLines: 0, "i", "s", null)); + } + + [Fact] + public void TheNodeLoggerIsRequired() + { + Assert.Throws(() => new ScriptLogger(null!, emit: null, maxLines: 1, "i", "s", null)); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs new file mode 100644 index 00000000..806e53c8 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs @@ -0,0 +1,168 @@ +using Microsoft.Extensions.Logging; +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts; + +/// +/// Flow Debugger step logs (design 2026-09-09 D6): the decorator installed over the script +/// context's logger while a run is traced. It must forward everything the node would have logged +/// anyway, capture Information and above as runtime rows — including levels the node's own +/// minimum level suppresses, because they are trace data, not node log output — and never capture +/// Debug/Trace chatter. +/// +public class TraceCapturingLoggerTests +{ + /// One row the sink's emitter received. + private sealed record Row(string Level, string Source, string Message, Exception? Exception, Guid? StepEventId); + + /// An inner logger that records what it was asked to write, at a configurable minimum level. + private sealed class RecordingLogger(LogLevel minimum = LogLevel.Trace) : ILogger + { + public List<(LogLevel Level, string Message)> Entries { get; } = []; + public List Scopes { get; } = []; + + public IDisposable? BeginScope(TState state) where TState : notnull + { + Scopes.Add(state); + return null; + } + + public bool IsEnabled(LogLevel logLevel) => logLevel >= minimum; + + public void Log(LogLevel level, EventId eventId, TState state, Exception? exception, Func formatter) => + Entries.Add((level, formatter(state, exception))); + } + + private static (TraceCapturingLogger Logger, RecordingLogger Inner, List Rows) Make(LogLevel innerMinimum = LogLevel.Trace) + { + var inner = new RecordingLogger(innerMinimum); + var rows = new List(); + var sink = new ScriptLogger( + new RecordingLogger(), + (level, source, message, exception, stepEventId) => rows.Add(new Row(level, source, message, exception, stepEventId)), + maxLines: 200, + instance: "CvdReactor01", + script: "OnHeartbeat", + executionId: Guid.NewGuid()); + return (new TraceCapturingLogger(inner, sink), inner, rows); + } + + [Fact] + public void Debug_IsForwarded_ButNotCaptured() + { + var (logger, inner, rows) = Make(); + + logger.LogDebug("internal chatter"); + + Assert.Single(inner.Entries); + Assert.Empty(rows); + } + + [Fact] + public void Warning_IsCapturedAsARuntimeRow_WithItsException() + { + var (logger, inner, rows) = Make(); + var boom = new TimeoutException("no reply"); + + logger.LogWarning(boom, "tag write timed out after {Ms} ms", 5_000); + + Assert.Single(inner.Entries); + var row = Assert.Single(rows); + Assert.Equal("warn", row.Level); + Assert.Equal("runtime", row.Source); + Assert.Equal("tag write timed out after 5000 ms", row.Message); + Assert.Same(boom, row.Exception); + } + + [Fact] + public void ErrorAndCritical_AreBothCapturedAsError() + { + var (logger, _, rows) = Make(); + + logger.LogError("bad"); + logger.LogCritical("worse"); + + Assert.Equal(["error", "error"], rows.Select(r => r.Level)); + } + + [Fact] + public void InformationIsEnabled_EvenWhenTheInnerLoggerSaysNo() + { + // A node whose Serilog minimum is Warning must still contribute Information lines to a trace. + var (logger, inner, rows) = Make(innerMinimum: LogLevel.Warning); + + Assert.False(inner.IsEnabled(LogLevel.Information)); + Assert.True(logger.IsEnabled(LogLevel.Information)); + + logger.LogInformation("captured anyway"); + + Assert.Empty(inner.Entries); + var row = Assert.Single(rows); + Assert.Equal("info", row.Level); + Assert.Equal("captured anyway", row.Message); + } + + [Fact] + public void BelowInformation_TheInnerLoggerDecidesEnablement() + { + var (logger, _, _) = Make(innerMinimum: LogLevel.Warning); + + Assert.False(logger.IsEnabled(LogLevel.Debug)); + } + + [Fact] + public void ADisabledInnerLogger_IsNotWrittenTo_ButTheRowIsStillCaptured() + { + var (logger, inner, rows) = Make(innerMinimum: LogLevel.Critical); + + logger.LogWarning("suppressed on the node"); + + Assert.Empty(inner.Entries); + Assert.Single(rows); + } + + [Fact] + public void CapturedLines_CarryTheAmbientStepId() + { + var (logger, _, rows) = Make(); + var stepId = Guid.NewGuid(); + + using (TraceStepScope.Enter(stepId)) + { + logger.LogInformation("inside the helper"); + } + + Assert.Equal(stepId, Assert.Single(rows).StepEventId); + } + + [Fact] + public void Ctor_RejectsAnAlreadyDecoratedLogger() + { + // Wrapping twice would forward each script line through two capture stages and emit two + // runtime rows per line — and would burn the run's line cap at double rate. + var (already, _, _) = Make(); + var sink = new ScriptLogger(new RecordingLogger(), emit: null, maxLines: 200, "i", "s", null); + + var ex = Assert.Throws(() => new TraceCapturingLogger(already, sink)); + Assert.Equal("inner", ex.ParamName); + } + + [Fact] + public void Ctor_RequiresBothCollaborators() + { + var sink = new ScriptLogger(new RecordingLogger(), emit: null, maxLines: 200, "i", "s", null); + + Assert.Throws(() => new TraceCapturingLogger(null!, sink)); + Assert.Throws(() => new TraceCapturingLogger(new RecordingLogger(), null!)); + } + + [Fact] + public void BeginScope_DelegatesToTheInnerLogger() + { + var (logger, inner, _) = Make(); + + logger.BeginScope("state"); + + Assert.Equal(["state"], inner.Scopes); + } +}