diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptLogger.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptLogger.cs index 3bbb9e79..e2a44bd4 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptLogger.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptLogger.cs @@ -165,7 +165,28 @@ public sealed class ScriptLogger } } - /// Applies the per-message cap, marking a truncated message with a trailing ellipsis. - private static string Clip(string? m) => - m is null ? string.Empty : m.Length <= MaxMessageChars ? m : m[..MaxMessageChars] + "…"; + /// + /// 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 index 50ad6d4c..ed71e6d0 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs @@ -18,12 +18,31 @@ namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; /// /// Installed only when the run is traced, so an untraced run keeps the bare inner logger. /// -/// The node logger every entry is forwarded to. -/// The run's , which owns the caps and the row emitter. -public sealed class TraceCapturingLogger(ILogger inner, ScriptLogger sink) : ILogger +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); + 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 @@ -31,16 +50,16 @@ public sealed class TraceCapturingLogger(ILogger inner, ScriptLogger sink) : ILo /// /// The level being tested. /// when the entry should be produced. - public bool IsEnabled(LogLevel level) => level >= LogLevel.Information || inner.IsEnabled(level); + 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)) + if (_inner.IsEnabled(level)) { - inner.Log(level, eventId, state, exception, formatter); + _inner.Log(level, eventId, state, exception, formatter); } if (level < LogLevel.Information || level == LogLevel.None) @@ -55,6 +74,6 @@ public sealed class TraceCapturingLogger(ILogger inner, ScriptLogger sink) : ILo _ => "error", }; - sink.Runtime(name, formatter(state, exception), exception); + _sink.Runtime(name, formatter(state, exception), exception); } } diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptLoggerTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptLoggerTests.cs index 251499eb..6c400c61 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptLoggerTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptLoggerTests.cs @@ -112,6 +112,32 @@ public class ScriptLoggerTests 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() { @@ -164,6 +190,33 @@ public class ScriptLoggerTests 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() { diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs index d9652f07..806e53c8 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs @@ -135,6 +135,27 @@ public class TraceCapturingLoggerTests 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() {