Files
lmxopcua/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptLogCompanionSinkTests.cs
Joseph Doherty 0a20de728d fix(core-scripting): resolve Low code-review findings (Core.Scripting-005,006,008,009,011)
- Core.Scripting-005: DependencyExtractor.HandleTagCall now recognises
  raw-string literal paths by checking the StringLiteralExpression node
  kind instead of the legacy StringLiteralToken kind.
- Core.Scripting-006: scope CompiledScriptCache failed-compile eviction
  with TryRemove(KeyValuePair) so a racing retry entry is not evicted.
- Core.Scripting-008: document the per-publish assembly accretion as an
  accepted limitation in docs/VirtualTags.md.
- Core.Scripting-009: enumerate the authoritative deny-list (namespace
  prefixes + type-granular denies) in the Phase 7 decision-#6 entry to
  match ForbiddenTypeAnalyzer.
- Core.Scripting-011: pin ScriptSandbox.Build, ScriptContext.Deadband
  boundary semantics, and end-to-end factory + companion-sink
  integration.

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

199 lines
8.3 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>
/// 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);
}
[Fact]
public void Factory_plus_companion_sink_integration_surfaces_script_error_in_both_logs()
{
// End-to-end Core.Scripting-011 coverage: an Error-level emission from a logger
// built by ScriptLoggerFactory must land in BOTH the per-script sink (acting as
// the scripts-*.log substitute here) AND the main-log companion at Warning level,
// tagged with the originating ScriptName property. This is the integration the
// server's logger pipeline relies on so operators see script failures in the
// primary log without monitoring the scripts file separately.
var scriptsSink = new CapturingSink();
var mainSink = new CapturingSink();
// Main pipeline — receives only Error+ events forwarded by the companion sink.
var mainLogger = new LoggerConfiguration()
.MinimumLevel.Verbose().WriteTo.Sink(mainSink).CreateLogger();
// Root script pipeline — fans out to the scripts sink (stand-in for the
// rolling scripts-*.log file) AND the companion sink that forwards Error+
// to the main logger.
var rootScriptLogger = new LoggerConfiguration()
.MinimumLevel.Verbose()
.WriteTo.Sink(scriptsSink)
.WriteTo.Sink(new ScriptLogCompanionSink(mainLogger))
.CreateLogger();
// Factory binds the per-script ScriptName property — this is the only way the
// mirror knows which script raised the event.
var factory = new ScriptLoggerFactory(rootScriptLogger);
var perScript = factory.Create("HighTemp");
perScript.Error("threshold exceeded");
// Scripts sink saw the Error at its original level with the ScriptName bound.
scriptsSink.Events.Count.ShouldBe(1);
scriptsSink.Events[0].Level.ShouldBe(LogEventLevel.Error);
((ScalarValue)scriptsSink.Events[0].Properties[ScriptLoggerFactory.ScriptNameProperty]).Value.ShouldBe("HighTemp");
// Main sink saw a Warning-level companion entry tagged with the same ScriptName.
mainSink.Events.Count.ShouldBe(1);
mainSink.Events[0].Level.ShouldBe(LogEventLevel.Warning);
((ScalarValue)mainSink.Events[0].Properties[ScriptLoggerFactory.ScriptNameProperty]).Value.ShouldBe("HighTemp");
((ScalarValue)mainSink.Events[0].Properties["OriginalLevel"]).Value.ShouldBe(LogEventLevel.Error);
}
}