diff --git a/src/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogCompanionSink.cs b/src/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogCompanionSink.cs new file mode 100644 index 0000000..2abc391 --- /dev/null +++ b/src/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogCompanionSink.cs @@ -0,0 +1,65 @@ +using Serilog; +using Serilog.Core; +using Serilog.Events; + +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; + +/// +/// Serilog sink that mirrors script log events at +/// or higher to a companion logger (typically the main opcua-*.log) at +/// . Lets operators see script errors in the +/// primary server log without drowning it in Debug/Info/Warning noise from scripts. +/// +/// +/// +/// Registered alongside the dedicated scripts-*.log rolling file sink in +/// the root script-logger configuration — events below Error land only in the +/// scripts file; Error/Fatal events land in both the scripts file (at original +/// level) and the main log (downgraded to Warning since the main log's audience +/// is server operators, not script authors). +/// +/// +/// The forwarded message preserves the ScriptName property so operators +/// reading the main log can tell which script raised the error at a glance. +/// Original exception (if any) is attached so the main log's diagnostics keep +/// the full stack trace. +/// +/// +public sealed class ScriptLogCompanionSink : ILogEventSink +{ + private readonly ILogger _mainLogger; + private readonly LogEventLevel _minMirrorLevel; + + public ScriptLogCompanionSink(ILogger mainLogger, LogEventLevel minMirrorLevel = LogEventLevel.Error) + { + _mainLogger = mainLogger ?? throw new ArgumentNullException(nameof(mainLogger)); + _minMirrorLevel = minMirrorLevel; + } + + public void Emit(LogEvent logEvent) + { + if (logEvent is null) return; + if (logEvent.Level < _minMirrorLevel) return; + + var scriptName = "unknown"; + if (logEvent.Properties.TryGetValue(ScriptLoggerFactory.ScriptNameProperty, out var prop) + && prop is ScalarValue sv && sv.Value is string s) + { + scriptName = s; + } + + var rendered = logEvent.RenderMessage(); + if (logEvent.Exception is not null) + { + _mainLogger.Warning(logEvent.Exception, + "[Script] {ScriptName} emitted {OriginalLevel}: {ScriptMessage}", + scriptName, logEvent.Level, rendered); + } + else + { + _mainLogger.Warning( + "[Script] {ScriptName} emitted {OriginalLevel}: {ScriptMessage}", + scriptName, logEvent.Level, rendered); + } + } +} diff --git a/src/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLoggerFactory.cs b/src/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLoggerFactory.cs new file mode 100644 index 0000000..be7ec6e --- /dev/null +++ b/src/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLoggerFactory.cs @@ -0,0 +1,48 @@ +using Serilog; + +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; + +/// +/// Creates per-script Serilog instances with the +/// ScriptName structured property pre-bound. Every log call from a user +/// script carries the owning virtual-tag or alarm name so operators can filter the +/// dedicated scripts-*.log sink by script in the Admin UI. +/// +/// +/// +/// Factory-based — the engine (Stream B / C) constructs exactly one instance +/// from the root script-logger pipeline at startup, then derives a per-script +/// logger for each it builds. No per-evaluation +/// allocation in the hot path. +/// +/// +/// The wrapped root logger is responsible for output wiring — typically a +/// rolling file sink to scripts-*.log plus a +/// that forwards Error-or-higher events +/// to the main server log at Warning level so operators see script errors +/// in the primary log without drowning it in Info noise. +/// +/// +public sealed class ScriptLoggerFactory +{ + /// Structured property name the enricher binds. Stable for log filtering. + public const string ScriptNameProperty = "ScriptName"; + + private readonly ILogger _rootLogger; + + public ScriptLoggerFactory(ILogger rootLogger) + { + _rootLogger = rootLogger ?? throw new ArgumentNullException(nameof(rootLogger)); + } + + /// + /// Create a per-script logger. Every event it emits carries + /// ScriptName= as a structured property. + /// + public ILogger Create(string scriptName) + { + if (string.IsNullOrWhiteSpace(scriptName)) + throw new ArgumentException("Script name is required.", nameof(scriptName)); + return _rootLogger.ForContext(ScriptNameProperty, scriptName); + } +} diff --git a/tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLogCompanionSinkTests.cs b/tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLogCompanionSinkTests.cs new file mode 100644 index 0000000..08ca420 --- /dev/null +++ b/tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLogCompanionSinkTests.cs @@ -0,0 +1,155 @@ +using Serilog; +using Serilog.Core; +using Serilog.Events; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; + +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests; + +/// +/// Verifies the sink that mirrors script Error+ events to the main log at Warning +/// level. Ensures script noise (Debug/Info/Warning) doesn't reach the main log +/// while genuine script failures DO surface there so operators see them without +/// watching a separate log file. +/// +[Trait("Category", "Unit")] +public sealed class ScriptLogCompanionSinkTests +{ + private sealed class CapturingSink : ILogEventSink + { + public List Events { get; } = []; + public void Emit(LogEvent logEvent) => Events.Add(logEvent); + } + + private static (ILogger script, CapturingSink scriptSink, CapturingSink mainSink) BuildPipeline() + { + // Main logger captures companion forwards. + var mainSink = new CapturingSink(); + var mainLogger = new LoggerConfiguration() + .MinimumLevel.Verbose().WriteTo.Sink(mainSink).CreateLogger(); + + // Script logger fans out to scripts file (here: capture sink) + the companion sink. + var scriptSink = new CapturingSink(); + var scriptLogger = new LoggerConfiguration() + .MinimumLevel.Verbose() + .WriteTo.Sink(scriptSink) + .WriteTo.Sink(new ScriptLogCompanionSink(mainLogger)) + .CreateLogger(); + + return (scriptLogger, scriptSink, mainSink); + } + + [Fact] + public void Info_event_lands_in_scripts_sink_but_not_in_main() + { + var (script, scriptSink, mainSink) = BuildPipeline(); + script.ForContext(ScriptLoggerFactory.ScriptNameProperty, "Test").Information("just info"); + + scriptSink.Events.Count.ShouldBe(1); + mainSink.Events.Count.ShouldBe(0); + } + + [Fact] + public void Warning_event_lands_in_scripts_sink_but_not_in_main() + { + var (script, scriptSink, mainSink) = BuildPipeline(); + script.ForContext(ScriptLoggerFactory.ScriptNameProperty, "Test").Warning("just a warning"); + + scriptSink.Events.Count.ShouldBe(1); + mainSink.Events.Count.ShouldBe(0); + } + + [Fact] + public void Error_event_mirrored_to_main_at_Warning_level() + { + var (script, scriptSink, mainSink) = BuildPipeline(); + script.ForContext(ScriptLoggerFactory.ScriptNameProperty, "MyAlarm") + .Error("condition script failed"); + + scriptSink.Events[0].Level.ShouldBe(LogEventLevel.Error); + mainSink.Events.Count.ShouldBe(1); + mainSink.Events[0].Level.ShouldBe(LogEventLevel.Warning, "Error+ is downgraded to Warning in the main log"); + } + + [Fact] + public void Mirrored_event_includes_ScriptName_and_original_level() + { + var (script, _, mainSink) = BuildPipeline(); + script.ForContext(ScriptLoggerFactory.ScriptNameProperty, "HighTemp") + .Error("temp exceeded limit"); + + var forwarded = mainSink.Events[0]; + forwarded.Properties.ShouldContainKey("ScriptName"); + ((ScalarValue)forwarded.Properties["ScriptName"]).Value.ShouldBe("HighTemp"); + forwarded.Properties.ShouldContainKey("OriginalLevel"); + ((ScalarValue)forwarded.Properties["OriginalLevel"]).Value.ShouldBe(LogEventLevel.Error); + } + + [Fact] + public void Mirrored_event_preserves_exception_for_main_log_stack_trace() + { + var (script, _, mainSink) = BuildPipeline(); + var ex = new InvalidOperationException("user code threw"); + script.ForContext(ScriptLoggerFactory.ScriptNameProperty, "BadScript").Error(ex, "boom"); + + mainSink.Events.Count.ShouldBe(1); + mainSink.Events[0].Exception.ShouldBeSameAs(ex); + } + + [Fact] + public void Fatal_event_mirrored_just_like_Error() + { + var (script, _, mainSink) = BuildPipeline(); + script.ForContext(ScriptLoggerFactory.ScriptNameProperty, "Fatal_Script").Fatal("catastrophic"); + mainSink.Events.Count.ShouldBe(1); + mainSink.Events[0].Level.ShouldBe(LogEventLevel.Warning); + } + + [Fact] + public void Missing_ScriptName_property_falls_back_to_unknown() + { + var (_, _, mainSink) = BuildPipeline(); + // Log without the ScriptName property to simulate a direct root-logger call + // that bypassed the factory (defensive — shouldn't normally happen). + var mainLogger = new LoggerConfiguration().CreateLogger(); + var companion = new ScriptLogCompanionSink(Log.Logger); + + // Build an event manually so we can omit the property. + var ev = new LogEvent( + timestamp: DateTimeOffset.UtcNow, + level: LogEventLevel.Error, + exception: null, + messageTemplate: new Serilog.Parsing.MessageTemplateParser().Parse("naked error"), + properties: []); + // Direct test: sink should not throw + message should be well-formed. + Should.NotThrow(() => companion.Emit(ev)); + } + + [Fact] + public void Null_main_logger_rejected() + { + Should.Throw(() => new ScriptLogCompanionSink(null!)); + } + + [Fact] + public void Custom_mirror_threshold_applied() + { + // Caller can raise the mirror threshold to Fatal if they want only + // catastrophic events in the main log. + var mainSink = new CapturingSink(); + var mainLogger = new LoggerConfiguration() + .MinimumLevel.Verbose().WriteTo.Sink(mainSink).CreateLogger(); + + var scriptLogger = new LoggerConfiguration() + .MinimumLevel.Verbose() + .WriteTo.Sink(new ScriptLogCompanionSink(mainLogger, LogEventLevel.Fatal)) + .CreateLogger(); + + scriptLogger.ForContext(ScriptLoggerFactory.ScriptNameProperty, "X").Error("error"); + mainSink.Events.Count.ShouldBe(0, "Error below configured Fatal threshold — not mirrored"); + + scriptLogger.ForContext(ScriptLoggerFactory.ScriptNameProperty, "X").Fatal("fatal"); + mainSink.Events.Count.ShouldBe(1); + } +} diff --git a/tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLoggerFactoryTests.cs b/tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLoggerFactoryTests.cs new file mode 100644 index 0000000..819879e --- /dev/null +++ b/tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLoggerFactoryTests.cs @@ -0,0 +1,94 @@ +using Serilog; +using Serilog.Core; +using Serilog.Events; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; + +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests; + +/// +/// Exercises the factory that creates per-script Serilog loggers with the +/// ScriptName structured property pre-bound. The property is what lets +/// Admin UI filter the scripts-*.log sink by which tag/alarm emitted each event. +/// +[Trait("Category", "Unit")] +public sealed class ScriptLoggerFactoryTests +{ + /// Capturing sink that collects every emitted LogEvent for assertion. + private sealed class CapturingSink : ILogEventSink + { + public List Events { get; } = []; + public void Emit(LogEvent logEvent) => Events.Add(logEvent); + } + + [Fact] + public void Create_sets_ScriptName_structured_property() + { + var sink = new CapturingSink(); + var root = new LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(sink).CreateLogger(); + var factory = new ScriptLoggerFactory(root); + + var logger = factory.Create("LineRate"); + logger.Information("hello"); + + sink.Events.Count.ShouldBe(1); + var ev = sink.Events[0]; + ev.Properties.ShouldContainKey(ScriptLoggerFactory.ScriptNameProperty); + ((ScalarValue)ev.Properties[ScriptLoggerFactory.ScriptNameProperty]).Value.ShouldBe("LineRate"); + } + + [Fact] + public void Each_script_gets_its_own_property_value() + { + var sink = new CapturingSink(); + var root = new LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(sink).CreateLogger(); + var factory = new ScriptLoggerFactory(root); + + factory.Create("Alarm_A").Information("event A"); + factory.Create("Tag_B").Warning("event B"); + factory.Create("Alarm_A").Error("event A again"); + + sink.Events.Count.ShouldBe(3); + ((ScalarValue)sink.Events[0].Properties[ScriptLoggerFactory.ScriptNameProperty]).Value.ShouldBe("Alarm_A"); + ((ScalarValue)sink.Events[1].Properties[ScriptLoggerFactory.ScriptNameProperty]).Value.ShouldBe("Tag_B"); + ((ScalarValue)sink.Events[2].Properties[ScriptLoggerFactory.ScriptNameProperty]).Value.ShouldBe("Alarm_A"); + } + + [Fact] + public void Error_level_event_preserves_level_and_exception() + { + var sink = new CapturingSink(); + var root = new LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(sink).CreateLogger(); + var factory = new ScriptLoggerFactory(root); + + factory.Create("Test").Error(new InvalidOperationException("boom"), "script failed"); + + sink.Events[0].Level.ShouldBe(LogEventLevel.Error); + sink.Events[0].Exception.ShouldBeOfType(); + } + + [Fact] + public void Null_root_rejected() + { + Should.Throw(() => new ScriptLoggerFactory(null!)); + } + + [Fact] + public void Empty_script_name_rejected() + { + var root = new LoggerConfiguration().CreateLogger(); + var factory = new ScriptLoggerFactory(root); + Should.Throw(() => factory.Create("")); + Should.Throw(() => factory.Create(" ")); + Should.Throw(() => factory.Create(null!)); + } + + [Fact] + public void ScriptNameProperty_constant_is_stable() + { + // Stability is an external contract — the Admin UI's log filter references + // this exact string. If it changes, the filter breaks silently. + ScriptLoggerFactory.ScriptNameProperty.ShouldBe("ScriptName"); + } +}