Compare commits

..

2 Commits

Author SHA1 Message Date
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
cb5d7b2d58 Merge pull request 'Phase 7 Stream A.2 — compile cache + per-evaluation timeout wrapper' (#178) from phase-7-stream-a2-cache-timeout into v2 2026-04-20 16:41:07 -04:00
4 changed files with 362 additions and 0 deletions

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

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

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

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