dohertj2/lmxopcua
1
0
Fork 0
Code Issues 5 Pull Requests 1 Actions Packages Projects Releases Wiki Activity

Merge pull request 'Phase 7 Stream A.3 — ScriptLoggerFactory + ScriptLogCompanionSink (closes Stream A)' (#179) from phase-7-stream-a3-script-logger into v2

Browse Source
This commit was merged in pull request #179.
This commit is contained in:
dohertj2
2026-04-20 16:45:09 -04:00
parent cb5d7b2d58 36774842cf
commit 00724e9784
4 changed files with 362 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files

65
src/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLogCompanionSink.cs Normal file
View File

@@ -0,0 +1,65 @@
using Serilog;
using Serilog.Core;
using Serilog.Events;
namespace ZB.MOM.WW.OtOpcUa.Core.Scripting;
/// <summary>
/// Serilog sink that mirrors script log events at <see cref="LogEventLevel.Error"/>
/// or higher to a companion logger (typically the main <c>opcua-*.log</c>) at
/// <see cref="LogEventLevel.Warning"/>. Lets operators see script errors in the
/// primary server log without drowning it in Debug/Info/Warning noise from scripts.
/// </summary>
/// <remarks>
/// <para>
/// Registered alongside the dedicated <c>scripts-*.log</c> 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).
/// </para>
/// <para>
/// The forwarded message preserves the <c>ScriptName</c> 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.
/// </para>
/// </remarks>
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);
}
}
}

48
src/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLoggerFactory.cs Normal file
View File

@@ -0,0 +1,48 @@
using Serilog;
namespace ZB.MOM.WW.OtOpcUa.Core.Scripting;
/// <summary>
/// Creates per-script Serilog <see cref="ILogger"/> instances with the
/// <c>ScriptName</c> 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 <c>scripts-*.log</c> sink by script in the Admin UI.
/// </summary>
/// <remarks>
/// <para>
/// 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 <see cref="ScriptContext"/> it builds. No per-evaluation
/// allocation in the hot path.
/// </para>
/// <para>
/// The wrapped root logger is responsible for output wiring — typically a
/// rolling file sink to <c>scripts-*.log</c> plus a
/// <see cref="ScriptLogCompanionSink"/> 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.
/// </para>
/// </remarks>
public sealed class ScriptLoggerFactory
{
/// <summary>Structured property name the enricher binds. Stable for log filtering.</summary>
public const string ScriptNameProperty = "ScriptName";
private readonly ILogger _rootLogger;
public ScriptLoggerFactory(ILogger rootLogger)
{
_rootLogger = rootLogger ?? throw new ArgumentNullException(nameof(rootLogger));
}
/// <summary>
/// Create a per-script logger. Every event it emits carries
/// <c>ScriptName=<paramref name="scriptName"/></c> as a structured property.
/// </summary>
public ILogger Create(string scriptName)
{
if (string.IsNullOrWhiteSpace(scriptName))
throw new ArgumentException("Script name is required.", nameof(scriptName));
return _rootLogger.ForContext(ScriptNameProperty, scriptName);
}
}

155
tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLogCompanionSinkTests.cs Normal file
View File

@@ -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;
/// <summary>
/// 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.
/// </summary>
[Trait("Category", "Unit")]
public sealed class ScriptLogCompanionSinkTests
{
private sealed class CapturingSink : ILogEventSink
{
public List<LogEvent> 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<ArgumentNullException>(() => 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);
}
}

94
tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLoggerFactoryTests.cs Normal file
View File

@@ -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;
/// <summary>
/// Exercises the factory that creates per-script Serilog loggers with the
/// <c>ScriptName</c> structured property pre-bound. The property is what lets
/// Admin UI filter the scripts-*.log sink by which tag/alarm emitted each event.
/// </summary>
[Trait("Category", "Unit")]
public sealed class ScriptLoggerFactoryTests
{
/// <summary>Capturing sink that collects every emitted LogEvent for assertion.</summary>
private sealed class CapturingSink : ILogEventSink
{
public List<LogEvent> 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<InvalidOperationException>();
}
[Fact]
public void Null_root_rejected()
{
Should.Throw<ArgumentNullException>(() => new ScriptLoggerFactory(null!));
}
[Fact]
public void Empty_script_name_rejected()
{
var root = new LoggerConfiguration().CreateLogger();
var factory = new ScriptLoggerFactory(root);
Should.Throw<ArgumentException>(() => factory.Create(""));
Should.Throw<ArgumentException>(() => factory.Create(" "));
Should.Throw<ArgumentException>(() => 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");
}
}