Files
lmxopcua/tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLoggerFactoryTests.cs
Joseph Doherty 36774842cf Phase 7 Stream A.3 — ScriptLoggerFactory + ScriptLogCompanionSink. Third of 3 increments closing out Stream A. Adds the Serilog plumbing that ties script-emitted log events to the dedicated scripts-*.log rolling sink with structured-property filtering AND forwards script Error+ events to the main opcua-*.log at Warning level so operators see script failures in the primary log without drowning it in Debug/Info script chatter. Both pieces are library-level building blocks — the actual file-sink + logger composition at server startup happens in Stream F (Admin UI) / Stream G (address-space wiring). This PR ships the reusable factory + sink + tests so any consumer can wire them up without rediscovering the structured-property contract.
ScriptLoggerFactory wraps a Serilog root logger (the scripts-*.log pipeline) and .Create(scriptName) returns a per-script ILogger with the ScriptName structured property pre-bound via ForContext. The structured property name is a public const (ScriptNameProperty = "ScriptName") because the Admin UI's log-viewer filter references this exact string — changing it breaks the filter silently, so it's stable by contract. Factory constructor rejects a null root logger; Create rejects null/empty/whitespace script names. No per-evaluation allocation in the hot path — engines (Stream B virtual-tag / Stream C scripted-alarm) create one factory per engine instance then cache per-script loggers beside the ScriptContext instances they already build.

ScriptLogCompanionSink is a Serilog ILogEventSink that forwards Error+ events from the script-logger pipeline to a separate "main" logger (the opcua-*.log pipeline in production) at Warning level. Rationale: operators usually watch the main server log, not scripts-*.log. Script authors log Info/Debug liberally during development — those stay in the scripts file. When a script actually fails (Error or Fatal), the operator needs to see it in the primary log so it can't be missed. Downgrading to Warning in the main log marks these as "needs attention but not a core server issue" since the server itself is healthy; the script author fixes the script. Forwarded event includes the ScriptName property (so operators can tell which script failed at a glance), the OriginalLevel (Error vs Fatal, preserved), the rendered message, and the original exception (preserved so the main log keeps the full stack trace — critical for diagnosis). Missing ScriptName property falls back to "unknown" without throwing; bypassing the factory is defensive but shouldn't happen in practice. Mirror threshold is configurable via constructor (defaults to LogEventLevel.Error) so deployments with stricter signal/noise requirements can raise it to Fatal.

15 new unit tests across two files. ScriptLoggerFactoryTests (6): Create sets the ScriptName structured property, each script gets its own property value across fan-out, Error-level event preserves level and exception, null root rejected, empty/whitespace/null name rejected, ScriptNameProperty const is stable at "ScriptName" (external-contract guard). ScriptLogCompanionSinkTests (9): Info/Warning events land in scripts sink only (not mirrored), Error event mirrored to main at Warning level (level-downgrade behavior), mirrored event includes ScriptName + OriginalLevel properties, mirrored event preserves exception for main-log stack-trace diagnosis, Fatal mirrored identically to Error, missing ScriptName falls back to "unknown" without throwing (defensive), null main logger rejected, custom mirror threshold (raised to Fatal) applied correctly.

Full Core.Scripting test suite after Stream A: 63/63 green (29 A.1 + 19 A.2 + 15 A.3). Stream A is complete — the scripting engine foundation, sandbox, sandbox-defense-in-depth, AST-inferred dependency extraction, compile cache, per-evaluation timeout, per-script logger with structured-property filtering, and companion-warn forwarding are all shipped and tested. Streams B through G build on this; Stream H closes out the phase with the compliance script + test baseline + merge to v2.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
2026-04-20 16:42:48 -04:00

95 lines
3.6 KiB
C#

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");
}
}