Phase 7 Stream A.3 — ScriptLoggerFactory + ScriptLogCompanionSink (closes Stream A) #179

Merged
dohertj2 merged 1 commits from phase-7-stream-a3-script-logger into v2 2026-04-20 16:45:11 -04:00
Owner

Third of 3 increments closing out Stream A. Library-level Serilog plumbing for per-script loggers + error-forwarding to the main log. Actual file-sink composition at server startup happens in Stream F / G; this PR ships the reusable building blocks.

ScriptLoggerFactory

  • Wraps a Serilog root logger; .Create(scriptName) returns an ILogger with ScriptName property pre-bound via ForContext
  • ScriptNameProperty = "ScriptName" is a public const — the Admin UI's log-viewer filter references this exact string, so changing it is a breaking contract guarded by a dedicated test
  • Rejects null root + null/empty/whitespace script names

ScriptLogCompanionSink

  • Serilog ILogEventSink that mirrors Error+ events from the scripts pipeline to the main logger (opcua-*.log) at Warning level — operators see script failures in the primary log without drowning it in Debug/Info chatter
  • Mirrored event preserves ScriptName + OriginalLevel + exception for stack-trace diagnosis
  • Missing ScriptName property falls back to "unknown" defensively
  • Mirror threshold constructor-configurable (default Error; deployments with stricter signal/noise can raise to Fatal)

Tests — 63/63 Core.Scripting

  • ScriptLoggerFactoryTests (6): Create binds ScriptName, per-script isolation, Error preserves level+exception, null/empty rejections, property-name const stability
  • ScriptLogCompanionSinkTests (9): Info/Warning NOT mirrored, Error/Fatal mirrored at Warning level, ScriptName+OriginalLevel+exception preserved on forward, missing-property fallback, null-logger rejected, custom threshold applied

Stream A complete

63/63 green — 29 A.1 (sandbox + AST inference) + 19 A.2 (cache + timeout) + 15 A.3 (loggers). Streams B-G build on this foundation; Stream H closes out the phase.

Third of 3 increments closing out Stream A. Library-level Serilog plumbing for per-script loggers + error-forwarding to the main log. Actual file-sink composition at server startup happens in Stream F / G; this PR ships the reusable building blocks. ## `ScriptLoggerFactory` - Wraps a Serilog root logger; `.Create(scriptName)` returns an `ILogger` with `ScriptName` property pre-bound via `ForContext` - `ScriptNameProperty = "ScriptName"` is a public const — the Admin UI's log-viewer filter references this exact string, so changing it is a breaking contract guarded by a dedicated test - Rejects null root + null/empty/whitespace script names ## `ScriptLogCompanionSink` - Serilog `ILogEventSink` that mirrors Error+ events from the scripts pipeline to the main logger (`opcua-*.log`) at Warning level — operators see script failures in the primary log without drowning it in Debug/Info chatter - Mirrored event preserves `ScriptName` + `OriginalLevel` + exception for stack-trace diagnosis - Missing `ScriptName` property falls back to "unknown" defensively - Mirror threshold constructor-configurable (default Error; deployments with stricter signal/noise can raise to Fatal) ## Tests — 63/63 Core.Scripting - `ScriptLoggerFactoryTests` (6): Create binds ScriptName, per-script isolation, Error preserves level+exception, null/empty rejections, property-name const stability - `ScriptLogCompanionSinkTests` (9): Info/Warning NOT mirrored, Error/Fatal mirrored at Warning level, ScriptName+OriginalLevel+exception preserved on forward, missing-property fallback, null-logger rejected, custom threshold applied ## Stream A complete 63/63 green — 29 A.1 (sandbox + AST inference) + 19 A.2 (cache + timeout) + 15 A.3 (loggers). Streams B-G build on this foundation; Stream H closes out the phase.
dohertj2 added 1 commit 2026-04-20 16:45:01 -04:00
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>
dohertj2 merged commit 00724e9784 into v2 2026-04-20 16:45:11 -04:00
Sign in to join this conversation.
No Reviewers
No Label
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: dohertj2/lmxopcua#179