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

2026-04-20T16:44:59-04:00

dohertj2 commented

2026-04-20 16:44:59 -04:00

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

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. 36774842cf

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

dohertj2 referenced this issue from a commit

2026-04-20 16:45:13 -04:00

Merge pull request 'Phase 7 Stream A.3 — ScriptLoggerFactory + ScriptLogCompanionSink (closes Stream A)' (#179) from phase-7-stream-a3-script-logger into v2

dohertj2 referenced this issue from a commit

2026-04-30 08:21:26 -04:00

AB CIP UDT Template Object shape reader. Closes the shape-reader half of task #179. CipTemplateObjectDecoder (pure-managed) parses the Read Template blob per Rockwell CIP Vol 1 + libplctag ab/cip.c handle_read_template_reply — 12-byte header (u16 member_count + u16 struct_handle + u32 instance_size + u32 member_def_size) followed by memberCount × 8-byte member blocks (u16 info with bit-15 struct flag + lower-12-bit type code matching the Symbol Object encoding, u16 array_size, u32 struct_offset) followed by semicolon-terminated strings (UDT name first, then one per member). ParseSemicolonTerminatedStrings handles the observed firmware variations — name;\0 vs name; delimiters, optional null/space padding after the semicolon, trailing-name-without-semicolon corner case. Struct-flag members decode as AbCipDataType.Structure; unknown atomic codes fall back to Structure so the shape remains valid even with unrecognised members. Zero member count + short buffer both return null; missing member names yield <member_N> placeholders. IAbCipTemplateReader + IAbCipTemplateReaderFactory abstraction — one call per template instance id returning the raw blob. LibplctagTemplateReader is the production implementation creating a libplctag Tag with name @udt/{templateId} + handing the buffer to the decoder. AbCipDriver ctor gains optional templateReaderFactory parameter (defaults to LibplctagTemplateReaderFactory) + new internal FetchUdtShapeAsync that — checks AbCipTemplateCache first, misses call the reader + decode + cache, template-read exceptions + decode failures return null so callers can fall back to declaration-driven fan-out without the whole discovery blowing up. OperationCanceledException rethrows for shutdown propagation. Unknown device host returns null without attempting a fetch. FlushOptionalCachesAsync empties the cache so a subsequent fetch re-reads. 16 new decoder tests — simple two-member UDT, struct-member flag → Structure, array member ArrayLength, 6-member mixed-type with correct offsets, unknown type code → Structure, zero member count → null, short buffer → null, missing member name → placeholder, ParseSemicolonTerminatedStrings theory across 5 shapes. 6 new AbCipFetchUdtShapeTests exercising the driver integration via reflection (method is internal) — happy-path decode + cache, different template ids get separate fetches, unknown device → null without reader creation, decode failure returns null + doesn't cache (next call retries), reader exception returns null, FlushOptionalCachesAsync clears the cache. Total AbCip unit tests now 211/211 passing (+19 from the @tags merge's 192); full solution builds 0 errors; other drivers untouched. Whole-UDT read optimization (single libplctag call returning the packed buffer + client-side member decode using the template offsets) is left as a follow-up — requires rethinking the per-tag read path + careful hardware validation; current per-member fan-out still works correctly, just with N round-trips instead of 1.

dohertj2 referenced this issue from a commit

2026-04-30 08:21:26 -04:00

AbCip whole-UDT read optimization (#194) — declaration-driven member grouping collapses N per-member reads into one parent-UDT read + client-side decode. Closes task #194. On a batch that includes multiple members of the same hand-declared UDT tag, ReadAsync now issues one libplctag read on the parent + decodes each member from the runtime's buffer at its computed byte offset. A 6-member Motor UDT read goes from 6 libplctag round-trips to 1 — the Rockwell-suggested pattern for minimizing CIP request overhead on batch reads of UDT state (decision #11's follow-through on what the template decoder from task #179 was meant to enable). AbCipUdtMemberLayout is a pure-function helper that computes declared-member byte offsets under Logix natural-alignment rules (SInt 1-byte / Int 2-byte / DInt + Real + Dt 4-byte / LInt + ULInt + LReal 8-byte; alignment pad inserted before each member as needed). Opts out for BOOL / String / Structure members — BOOL storage in Logix UDTs packs into a hidden host byte whose position can't be computed from declaration-only info, and String members need length-prefix + STRING[82] fan-out which libplctag already handles via a per-tag DecodeValue path. The CIP Template Object shape from task #179 (when populated via FetchUdtShapeAsync) carries real offsets for those members — layering that richer path on top of the planner is a separate follow-up and does not change this PR's conservative behaviour. AbCipUdtReadPlanner is the scheduling function ReadAsync consults each batch — pure over (requests, tagsByName), emits Groups + Fallbacks. A group is formed when (a) the reference resolves to "parent.member"; (b) parent is a Structure tag with declared Members; (c) the layout helper succeeds on those members; (d) the specific member appears in the computed offset map; (e) at least two members of the same parent appear in the batch — single-member groups demote to the fallback path because one whole-UDT read vs one per-member read is equivalent cost but more client-side work. Original batch indices are preserved through the plan so out-of-order batches write decoded values back at the right output slot; the caller's result array order is invariant. IAbCipTagRuntime.DecodeValueAt(AbCipDataType, int offset, int? bitIndex) is the new hot-path method — LibplctagTagRuntime delegates to libplctag's offset-aware Get*(offset) calls (GetInt32, GetFloat32, etc.) that were always there; previously every call passed offset 0. DecodeValue(type, bitIndex) stays as the shorthand + forwards to DecodeValueAt with offset 0, preserving the existing single-tag read path + every test that exercises it. FakeAbCipTag gains a ValuesByOffset dictionary so tests can drive multi-member decoding by setting offset→value before the read fires; unmapped offsets fall back to the existing Value field so the 200+ existing tests that never set ValuesByOffset keep working unchanged. AbCipDriver.ReadAsync refactored: planner splits the batch, ReadGroupAsync handles each UDT group (one EnsureTagRuntimeAsync on the parent + one ReadAsync + N DecodeValueAt calls), ReadSingleAsync handles each fallback (the pre-#194 per-tag path, now extracted + threaded through). A per-group failure stamps the mapped libplctag status across every grouped member only — sibling groups + fallback refs are unaffected. Health-surface updates happen once per successful group rather than once per member to avoid ping-ponging the DriverState bookkeeping. Five AbCipUdtMemberLayoutTests: packed atomics get natural-alignment offsets including 8-byte pad before LInt; SInts pack without padding; BOOL/String/Structure opt out + return null; empty member list returns null. Six AbCipUdtReadPlannerTests: two members group; single-member demotes to fallback; unknown references fall back without poisoning groups; atomic top-level tags fall back untouched; UDTs containing BOOL don't group; original indices survive out-of-order batches. Five AbCipDriverWholeUdtReadTests (real driver + fake runtime): two grouped members trigger exactly one parent read + one fake runtime (proving the optimization engages); each member decodes at its own offset via ValuesByOffset; parent-read non-zero status stamps Bad across the group; mixed UDT-member + atomic top-level batch produces 2 runtimes + 2 reads (not 3); single-member-of-UDT still uses the member-level runtime (proving demotion works). Driver builds 0 errors; AbCip.Tests 227/227 (was 211, +16 new).