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); // M3: worded identically to the central InboundScriptLogger closing row. Assert.Contains("2 further log line(s) were not captured", closing.Message); Assert.Contains("ScadaBridge:SiteRuntime:MaxLogLinesPerRun = 3", 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 further log line(s) were not captured", 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)); } }