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>
This commit is contained in:
Joseph Doherty
2026-04-20 16:42:48 -04:00
parent cb5d7b2d58
commit 36774842cf
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);
}
}
}