Compare commits

..

4 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
Joseph Doherty
0ae715cca4 Phase 7 Stream A.2 — compile cache + per-evaluation timeout wrapper. Second of 3 increments within Stream A. Adds two independent resilience primitives that the virtual-tag engine (Stream B) and scripted-alarm engine (Stream C) will compose with the base ScriptEvaluator. Both are generic on (TContext, TResult) so different engines get their own instances without cross-contamination.
CompiledScriptCache<TContext, TResult> — source-hash-keyed cache of compiled evaluators. Roslyn compilation is the most expensive step in the evaluator pipeline (5-20ms per script depending on size); re-compiling on every value-change event would starve the engine. ConcurrentDictionary of Lazy<ScriptEvaluator> with ExecutionAndPublication mode ensures concurrent callers never double-compile even on a cold cache race. Failed compiles evict the cache entry so an Admin UI retry with corrected source actually recompiles (otherwise the cached exception would persist). Whitespace-sensitive hash — reformatting a script misses the cache on purpose, simpler than AST-canonicalize and happens rarely. No capacity bound because virtual-tag + alarm scripts are config-DB bounded (thousands, not millions); if scale pushes past that in v3 an LRU eviction slots in behind the same API.

TimedScriptEvaluator<TContext, TResult> — wraps a ScriptEvaluator with a per-evaluation wall-clock timeout (default 250ms per Phase 7 plan Stream A.4, configurable per tag so slower backends can widen). Critical implementation detail: the underlying Roslyn ScriptRunner executes synchronously on the calling thread for CPU-bound user scripts, returning an already-completed Task before the caller can register a timeout. Naive `Task.WaitAsync(timeout)` would see the completed task and never fire. Fix: push evaluation to a thread-pool thread via Task.Run, so the caller's thread is free to wait and the timeout reliably fires after the configured budget. Known trade-off (documented in the class summary): when a script times out, the underlying evaluation task continues running on the thread-pool thread until Roslyn returns; in the CPU-bound-infinite-loop case it's effectively leaked until the runtime decides to unwind. Tighter CPU budgeting would require an out-of-process script runner (v3 concern). In practice the timeout + structured warning log surfaces the offending script so the operator fixes it, and the orphan thread is rare. Caller-supplied CancellationToken is honored and takes precedence over the timeout, so driver-shutdown paths see a clean OperationCanceledException rather than a misclassified ScriptTimeoutException.

ScriptTimeoutException carries the configured Timeout and a diagnostic message pointing the operator at ctx.Logger output around the failure plus suggesting widening the timeout, simplifying the script, or moving heavy work out of the evaluation path. The virtual-tag engine (Stream B) will catch this and map the owning tag's quality to BadInternalError per Phase 7 decision #11, logging a structured warning with the offending script name.

Tests: CompiledScriptCacheTests (10) — first-call compile, identical-source dedupe to same instance, different-source produces different evaluator, whitespace-sensitivity documented, cached evaluator still runs correctly, failed compile evicted for retry, Clear drops entries, concurrent GetOrCompile of the same source deduplicates to one instance, different TContext/TResult use separate cache instances, null source rejected. TimedScriptEvaluatorTests (9) — fast script completes under timeout, CPU-bound script throws ScriptTimeoutException, caller cancellation takes precedence over timeout (shutdown path correctness), default 250ms per plan, zero/negative timeout rejected at construction, null inner rejected, null context rejected, user-thrown exceptions propagate unwrapped (not conflated with timeout), timeout exception message contains diagnostic guidance. Full suite: 48/48 green (29 from A.1 + 19 new).

Next: Stream A.3 wires the dedicated scripts-*.log Serilog rolling sink + structured-property filtering + companion-WARN enricher to the main log, closing out Stream A.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
2026-04-20 16:38:43 -04:00
d2bfcd9f1e Merge pull request 'Phase 7 Stream A.1 — Core.Scripting project scaffold + ScriptContext + sandbox + AST dependency extractor' (#177) from phase-7-stream-a1-core-scripting into v2 2026-04-20 16:29:44 -04:00
8 changed files with 832 additions and 0 deletions

View File

@@ -0,0 +1,83 @@
using System.Collections.Concurrent;
using System.Security.Cryptography;
using System.Text;
namespace ZB.MOM.WW.OtOpcUa.Core.Scripting;
/// <summary>
/// Source-hash-keyed compile cache for user scripts. Roslyn compilation is the most
/// expensive step in the evaluator pipeline (5-20ms per script depending on size);
/// re-compiling on every value-change event would starve the virtual-tag engine.
/// The cache is generic on the <see cref="ScriptContext"/> subclass + result type so
/// different engines (virtual-tag / alarm-predicate / future alarm-action) each get
/// their own cache instance — there's no cross-type pollution.
/// </summary>
/// <remarks>
/// <para>
/// Concurrent-safe: <see cref="ConcurrentDictionary{TKey, TValue}"/> of
/// <see cref="Lazy{T}"/> means a miss on two threads compiles exactly once.
/// <see cref="LazyThreadSafetyMode.ExecutionAndPublication"/> guarantees other
/// threads block on the in-flight compile rather than racing to duplicate work.
/// </para>
/// <para>
/// Cache is keyed on SHA-256 of the UTF-8 bytes of the source — collision-free in
/// practice. Whitespace changes therefore miss the cache on purpose; operators
/// see re-compile time on their first evaluation after a format-only edit which
/// is rare and benign.
/// </para>
/// <para>
/// No capacity bound. Virtual-tag + alarm scripts are operator-authored and
/// bounded by config DB (typically low thousands). If that changes in v3, add an
/// LRU eviction policy — the API stays the same.
/// </para>
/// </remarks>
public sealed class CompiledScriptCache<TContext, TResult>
where TContext : ScriptContext
{
private readonly ConcurrentDictionary<string, Lazy<ScriptEvaluator<TContext, TResult>>> _cache = new();
/// <summary>
/// Return the compiled evaluator for <paramref name="scriptSource"/>, compiling
/// on first sight + reusing thereafter. If the source fails to compile, the
/// original Roslyn / sandbox exception propagates; the cache entry is removed so
/// the next call retries (useful during Admin UI authoring when the operator is
/// still fixing syntax).
/// </summary>
public ScriptEvaluator<TContext, TResult> GetOrCompile(string scriptSource)
{
if (scriptSource is null) throw new ArgumentNullException(nameof(scriptSource));
var key = HashSource(scriptSource);
var lazy = _cache.GetOrAdd(key, _ => new Lazy<ScriptEvaluator<TContext, TResult>>(
() => ScriptEvaluator<TContext, TResult>.Compile(scriptSource),
LazyThreadSafetyMode.ExecutionAndPublication));
try
{
return lazy.Value;
}
catch
{
// Failed compile — evict so a retry with corrected source can succeed.
_cache.TryRemove(key, out _);
throw;
}
}
/// <summary>Current entry count. Exposed for Admin UI diagnostics / tests.</summary>
public int Count => _cache.Count;
/// <summary>Drop every cached compile. Used on config generation publish + tests.</summary>
public void Clear() => _cache.Clear();
/// <summary>True when the exact source has been compiled at least once + is still cached.</summary>
public bool Contains(string scriptSource)
=> _cache.ContainsKey(HashSource(scriptSource));
private static string HashSource(string source)
{
var bytes = Encoding.UTF8.GetBytes(source);
var hash = SHA256.HashData(bytes);
return Convert.ToHexString(hash);
}
}

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,102 @@
namespace ZB.MOM.WW.OtOpcUa.Core.Scripting;
/// <summary>
/// Wraps a <see cref="ScriptEvaluator{TContext, TResult}"/> with a per-evaluation
/// wall-clock timeout. Default is 250ms per Phase 7 plan Stream A.4; configurable
/// per tag so deployments with slower backends can widen it.
/// </summary>
/// <remarks>
/// <para>
/// Implemented with <see cref="Task.WaitAsync(TimeSpan, CancellationToken)"/>
/// rather than a cancellation-token-only approach because Roslyn-compiled
/// scripts don't internally poll the cancellation token unless the user code
/// does async work. A CPU-bound infinite loop in a script won't honor a
/// cooperative cancel — <c>WaitAsync</c> returns control when the timeout fires
/// regardless of whether the inner task completes.
/// </para>
/// <para>
/// <b>Known limitation:</b> when a script times out, the underlying ScriptRunner
/// task continues running on a thread-pool thread until the Roslyn runtime
/// returns. In the CPU-bound-infinite-loop case that's effectively "leaked" —
/// the thread is tied up until the runtime decides to return, which it may
/// never do. Phase 7 plan Stream A.4 accepts this as a known trade-off; tighter
/// CPU budgeting would require an out-of-process script runner, which is a v3
/// concern. In practice, the timeout + structured warning log surfaces the
/// offending script so the operator can fix it; the orphan thread is rare.
/// </para>
/// <para>
/// Caller-supplied <see cref="CancellationToken"/> is honored — if the caller
/// cancels before the timeout fires, the caller's cancel wins and the
/// <see cref="OperationCanceledException"/> propagates (not wrapped as
/// <see cref="ScriptTimeoutException"/>). That distinction matters: the
/// virtual-tag engine's shutdown path cancels scripts on dispose; it shouldn't
/// see those as timeouts.
/// </para>
/// </remarks>
public sealed class TimedScriptEvaluator<TContext, TResult>
where TContext : ScriptContext
{
/// <summary>Default timeout per Phase 7 plan Stream A.4 — 250ms.</summary>
public static readonly TimeSpan DefaultTimeout = TimeSpan.FromMilliseconds(250);
private readonly ScriptEvaluator<TContext, TResult> _inner;
/// <summary>Wall-clock budget per evaluation. Script exceeding this throws <see cref="ScriptTimeoutException"/>.</summary>
public TimeSpan Timeout { get; }
public TimedScriptEvaluator(ScriptEvaluator<TContext, TResult> inner)
: this(inner, DefaultTimeout)
{
}
public TimedScriptEvaluator(ScriptEvaluator<TContext, TResult> inner, TimeSpan timeout)
{
_inner = inner ?? throw new ArgumentNullException(nameof(inner));
if (timeout <= TimeSpan.Zero)
throw new ArgumentOutOfRangeException(nameof(timeout), "Timeout must be positive.");
Timeout = timeout;
}
public async Task<TResult> RunAsync(TContext context, CancellationToken ct = default)
{
if (context is null) throw new ArgumentNullException(nameof(context));
// Push evaluation to a thread-pool thread so a CPU-bound script (e.g. a tight
// loop with no async work) doesn't hog the caller's thread before WaitAsync
// gets to register its timeout. Without this, Roslyn's ScriptRunner executes
// synchronously on the calling thread and returns an already-completed Task,
// so WaitAsync sees a completed task and never fires the timeout.
var runTask = Task.Run(() => _inner.RunAsync(context, ct), ct);
try
{
return await runTask.WaitAsync(Timeout, ct).ConfigureAwait(false);
}
catch (TimeoutException)
{
// WaitAsync's synthesized timeout — the inner task may still be running
// on its thread-pool thread (known leak documented in the class summary).
// Wrap so callers can distinguish from user-written timeout logic.
throw new ScriptTimeoutException(Timeout);
}
}
}
/// <summary>
/// Thrown when a script evaluation exceeds its configured timeout. The virtual-tag
/// engine (Stream B) catches this + maps the owning tag's quality to
/// <c>BadInternalError</c> per Phase 7 plan decision #11, logging a structured
/// warning with the offending script name so operators can locate + fix it.
/// </summary>
public sealed class ScriptTimeoutException : Exception
{
public TimeSpan Timeout { get; }
public ScriptTimeoutException(TimeSpan timeout)
: base($"Script evaluation exceeded the configured timeout of {timeout.TotalMilliseconds:F1} ms. " +
"The script was either CPU-bound or blocked on a slow operation; check ctx.Logger output " +
"around the timeout and consider widening the timeout per tag, simplifying the script, or " +
"moving heavy work out of the evaluation path.")
{
Timeout = timeout;
}
}

View File

@@ -0,0 +1,151 @@
using Shouldly;
using Xunit;
using ZB.MOM.WW.OtOpcUa.Core.Scripting;
namespace ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests;
/// <summary>
/// Exercises the source-hash keyed compile cache. Roslyn compilation is the most
/// expensive step in the evaluator pipeline; this cache collapses redundant
/// compiles of unchanged scripts to zero-cost lookups + makes sure concurrent
/// callers never double-compile.
/// </summary>
[Trait("Category", "Unit")]
public sealed class CompiledScriptCacheTests
{
private sealed class CompileCountingGate
{
public int Count;
}
[Fact]
public void First_call_compiles_and_caches()
{
var cache = new CompiledScriptCache<FakeScriptContext, int>();
cache.Count.ShouldBe(0);
var e = cache.GetOrCompile("""return 42;""");
e.ShouldNotBeNull();
cache.Count.ShouldBe(1);
cache.Contains("""return 42;""").ShouldBeTrue();
}
[Fact]
public void Identical_source_returns_the_same_compiled_evaluator()
{
var cache = new CompiledScriptCache<FakeScriptContext, int>();
var first = cache.GetOrCompile("""return 1;""");
var second = cache.GetOrCompile("""return 1;""");
ReferenceEquals(first, second).ShouldBeTrue();
cache.Count.ShouldBe(1);
}
[Fact]
public void Different_source_produces_different_evaluator()
{
var cache = new CompiledScriptCache<FakeScriptContext, int>();
var a = cache.GetOrCompile("""return 1;""");
var b = cache.GetOrCompile("""return 2;""");
ReferenceEquals(a, b).ShouldBeFalse();
cache.Count.ShouldBe(2);
}
[Fact]
public void Whitespace_difference_misses_cache()
{
// Documented behavior: reformatting a script recompiles. Simpler + cheaper
// than the alternative (AST-canonicalize then hash) and doesn't happen often.
var cache = new CompiledScriptCache<FakeScriptContext, int>();
cache.GetOrCompile("""return 1;""");
cache.GetOrCompile("return 1; "); // trailing whitespace — different hash
cache.Count.ShouldBe(2);
}
[Fact]
public async Task Cached_evaluator_still_runs_correctly()
{
var cache = new CompiledScriptCache<FakeScriptContext, double>();
var e = cache.GetOrCompile("""return (double)ctx.GetTag("In").Value * 3.0;""");
var ctx = new FakeScriptContext().Seed("In", 7.0);
// Run twice through the cache — both must return the same correct value.
var first = await e.RunAsync(ctx, TestContext.Current.CancellationToken);
var second = await cache.GetOrCompile("""return (double)ctx.GetTag("In").Value * 3.0;""")
.RunAsync(ctx, TestContext.Current.CancellationToken);
first.ShouldBe(21.0);
second.ShouldBe(21.0);
}
[Fact]
public void Failed_compile_is_evicted_so_retry_with_corrected_source_works()
{
var cache = new CompiledScriptCache<FakeScriptContext, int>();
// First attempt — undefined identifier, compile throws.
Should.Throw<Exception>(() => cache.GetOrCompile("""return unknownIdentifier + 1;"""));
cache.Count.ShouldBe(0, "failed compile must be evicted so retry can re-attempt");
// Retry with corrected source succeeds + caches.
cache.GetOrCompile("""return 42;""").ShouldNotBeNull();
cache.Count.ShouldBe(1);
}
[Fact]
public void Clear_drops_every_entry()
{
var cache = new CompiledScriptCache<FakeScriptContext, int>();
cache.GetOrCompile("""return 1;""");
cache.GetOrCompile("""return 2;""");
cache.Count.ShouldBe(2);
cache.Clear();
cache.Count.ShouldBe(0);
cache.Contains("""return 1;""").ShouldBeFalse();
}
[Fact]
public void Concurrent_compiles_of_the_same_source_deduplicate()
{
// LazyThreadSafetyMode.ExecutionAndPublication guarantees only one compile
// even when multiple threads race GetOrCompile against an empty cache.
// We can't directly count Roslyn compilations — but we can assert all
// concurrent callers see the same evaluator instance.
var cache = new CompiledScriptCache<FakeScriptContext, int>();
const string src = """return 99;""";
var tasks = Enumerable.Range(0, 20)
.Select(_ => Task.Run(() => cache.GetOrCompile(src)))
.ToArray();
Task.WhenAll(tasks).GetAwaiter().GetResult();
var firstInstance = tasks[0].Result;
foreach (var t in tasks)
ReferenceEquals(t.Result, firstInstance).ShouldBeTrue();
cache.Count.ShouldBe(1);
}
[Fact]
public void Different_TContext_TResult_pairs_use_separate_cache_instances()
{
// Documented: each engine (virtual-tag / alarm-predicate / alarm-action) owns
// its own cache. The type-parametric design makes this the default without
// cross-contamination at the dictionary level.
var intCache = new CompiledScriptCache<FakeScriptContext, int>();
var boolCache = new CompiledScriptCache<FakeScriptContext, bool>();
intCache.GetOrCompile("""return 1;""");
boolCache.GetOrCompile("""return true;""");
intCache.Count.ShouldBe(1);
boolCache.Count.ShouldBe(1);
intCache.Contains("""return true;""").ShouldBeFalse();
boolCache.Contains("""return 1;""").ShouldBeFalse();
}
[Fact]
public void Null_source_throws_ArgumentNullException()
{
var cache = new CompiledScriptCache<FakeScriptContext, int>();
Should.Throw<ArgumentNullException>(() => cache.GetOrCompile(null!));
}
}

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

View File

@@ -0,0 +1,134 @@
using Shouldly;
using Xunit;
using ZB.MOM.WW.OtOpcUa.Core.Scripting;
namespace ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests;
/// <summary>
/// Verifies the per-evaluation timeout wrapper. Fast scripts complete normally;
/// CPU-bound or hung scripts throw <see cref="ScriptTimeoutException"/> instead of
/// starving the engine. Caller-supplied cancellation tokens take precedence over the
/// timeout so driver-shutdown paths see a clean cancel rather than a timeout.
/// </summary>
[Trait("Category", "Unit")]
public sealed class TimedScriptEvaluatorTests
{
[Fact]
public async Task Fast_script_completes_under_timeout_and_returns_value()
{
var inner = ScriptEvaluator<FakeScriptContext, double>.Compile(
"""return (double)ctx.GetTag("In").Value + 1.0;""");
var timed = new TimedScriptEvaluator<FakeScriptContext, double>(
inner, TimeSpan.FromSeconds(1));
var ctx = new FakeScriptContext().Seed("In", 41.0);
var result = await timed.RunAsync(ctx, TestContext.Current.CancellationToken);
result.ShouldBe(42.0);
}
[Fact]
public async Task Script_longer_than_timeout_throws_ScriptTimeoutException()
{
// Scripts can't easily do Thread.Sleep in the sandbox (System.Threading.Thread
// is denied). But a tight CPU loop exceeds any short timeout.
var inner = ScriptEvaluator<FakeScriptContext, int>.Compile(
"""
var end = Environment.TickCount64 + 5000;
while (Environment.TickCount64 < end) { }
return 1;
""");
var timed = new TimedScriptEvaluator<FakeScriptContext, int>(
inner, TimeSpan.FromMilliseconds(50));
var ex = await Should.ThrowAsync<ScriptTimeoutException>(async () =>
await timed.RunAsync(new FakeScriptContext(), TestContext.Current.CancellationToken));
ex.Timeout.ShouldBe(TimeSpan.FromMilliseconds(50));
ex.Message.ShouldContain("50.0");
}
[Fact]
public async Task Caller_cancellation_takes_precedence_over_timeout()
{
// A CPU-bound script that would otherwise timeout; external ct fires first.
// Expected: OperationCanceledException (not ScriptTimeoutException) so shutdown
// paths aren't misclassified as timeouts.
var inner = ScriptEvaluator<FakeScriptContext, int>.Compile(
"""
var end = Environment.TickCount64 + 10000;
while (Environment.TickCount64 < end) { }
return 1;
""");
var timed = new TimedScriptEvaluator<FakeScriptContext, int>(
inner, TimeSpan.FromSeconds(5));
using var cts = new CancellationTokenSource(TimeSpan.FromMilliseconds(80));
await Should.ThrowAsync<OperationCanceledException>(async () =>
await timed.RunAsync(new FakeScriptContext(), cts.Token));
}
[Fact]
public void Default_timeout_is_250ms_per_plan()
{
TimedScriptEvaluator<FakeScriptContext, int>.DefaultTimeout
.ShouldBe(TimeSpan.FromMilliseconds(250));
}
[Fact]
public void Zero_or_negative_timeout_is_rejected_at_construction()
{
var inner = ScriptEvaluator<FakeScriptContext, int>.Compile("""return 1;""");
Should.Throw<ArgumentOutOfRangeException>(() =>
new TimedScriptEvaluator<FakeScriptContext, int>(inner, TimeSpan.Zero));
Should.Throw<ArgumentOutOfRangeException>(() =>
new TimedScriptEvaluator<FakeScriptContext, int>(inner, TimeSpan.FromMilliseconds(-1)));
}
[Fact]
public void Null_inner_is_rejected()
{
Should.Throw<ArgumentNullException>(() =>
new TimedScriptEvaluator<FakeScriptContext, int>(null!));
}
[Fact]
public void Null_context_is_rejected()
{
var inner = ScriptEvaluator<FakeScriptContext, int>.Compile("""return 1;""");
var timed = new TimedScriptEvaluator<FakeScriptContext, int>(inner);
Should.ThrowAsync<ArgumentNullException>(async () =>
await timed.RunAsync(null!, TestContext.Current.CancellationToken));
}
[Fact]
public async Task Script_exception_propagates_unwrapped()
{
// User-thrown exceptions must come through as-is — NOT wrapped in
// ScriptTimeoutException. The virtual-tag engine catches them per-tag and
// maps to BadInternalError; conflating with timeout would lose that info.
var inner = ScriptEvaluator<FakeScriptContext, int>.Compile(
"""throw new InvalidOperationException("script boom");""");
var timed = new TimedScriptEvaluator<FakeScriptContext, int>(inner, TimeSpan.FromSeconds(1));
var ex = await Should.ThrowAsync<InvalidOperationException>(async () =>
await timed.RunAsync(new FakeScriptContext(), TestContext.Current.CancellationToken));
ex.Message.ShouldBe("script boom");
}
[Fact]
public async Task ScriptTimeoutException_message_points_at_diagnostic_path()
{
var inner = ScriptEvaluator<FakeScriptContext, int>.Compile(
"""
var end = Environment.TickCount64 + 5000;
while (Environment.TickCount64 < end) { }
return 1;
""");
var timed = new TimedScriptEvaluator<FakeScriptContext, int>(
inner, TimeSpan.FromMilliseconds(30));
var ex = await Should.ThrowAsync<ScriptTimeoutException>(async () =>
await timed.RunAsync(new FakeScriptContext(), TestContext.Current.CancellationToken));
ex.Message.ShouldContain("ctx.Logger");
ex.Message.ShouldContain("widening the timeout");
}
}