Compare commits
2 Commits
phase-7-st
...
phase-7-st
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
36774842cf | ||
| cb5d7b2d58 |
@@ -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
48
src/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptLoggerFactory.cs
Normal 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);
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -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);
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -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");
|
||||||
|
}
|
||||||
|
}
|
||||||
Reference in New Issue
Block a user