Files
lmxopcua/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverTests.cs
T
Joseph Doherty 5c8d6f6f98 test(calc): make the not-evaluated-inline assertion exact, not thread-id based
The first form compared the publish's managed thread id with the caller's, which flaked
(1 in 6): the evaluation pump may reuse the pooled thread the test released while awaiting
the drain, so an id match proves nothing. It now sets a ThreadLocal flag for exactly the
OnDependencyValue window, so 'published inline' is answered on the stack rather than by
thread identity. Re-falsified by making SchedulePump run the pump synchronously (red
immediately, reverted); 5 consecutive clean suite runs after.
2026-08-10 08:07:27 -04:00

438 lines
23 KiB
C#

using System.Collections.Concurrent;
using Microsoft.Extensions.Logging;
using Serilog;
using Serilog.Events;
using Shouldly;
using Xunit;
using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging;
using ZB.MOM.WW.OtOpcUa.Core.Abstractions;
using ZB.MOM.WW.OtOpcUa.Core.Scripting;
namespace ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests;
/// <summary>
/// WP7 unit tests for <see cref="CalculationDriver"/>: dependency-ref extraction from the authored
/// tags, the change-gate (no publish until every declared dep has arrived), value dedup, the
/// Good→Bad transition + <c>ScriptLogEntry</c> emission + Good recovery, and timer-trigger recompute.
/// </summary>
public sealed class CalculationDriverTests
{
private const uint StatusGood = 0u;
private const uint StatusBadInternalError = 0x80020000u;
private const uint StatusBadWaitingForInitialData = 0x80320000u;
private static RawTagEntry CalcTag(string rawPath, string source, bool changeTriggered = true, int? timerMs = null)
{
var timer = timerMs is { } ms ? $",\"timerIntervalMs\":{ms}" : "";
var json = $"{{\"scriptId\":\"s-{rawPath}\",\"changeTriggered\":{(changeTriggered ? "true" : "false")}{timer}," +
$"\"scriptSource\":{System.Text.Json.JsonSerializer.Serialize(source)}}}";
return new RawTagEntry(rawPath, json, WriteIdempotent: false);
}
private static (CalculationDriver Driver, ConcurrentQueue<DataChangeEventArgs> Published, List<ScriptLogEntry> Logs)
Build(params RawTagEntry[] tags)
{
var logs = new List<ScriptLogEntry>();
var sink = new ScriptLogTopicSink(new CapturingPublisher(logs), LogEventLevel.Information);
var scriptRoot = new ScriptRootLogger(new LoggerConfiguration().WriteTo.Sink(sink).CreateLogger());
var driver = new CalculationDriver(new CalculationDriverOptions { RawTags = tags }, "calc-drv", scriptRoot);
var published = new ConcurrentQueue<DataChangeEventArgs>();
driver.OnDataChange += (_, e) => published.Enqueue(e);
return (driver, published, logs);
}
/// <summary>
/// Wait until the driver's evaluation pump has drained. A change-triggered evaluation is queued by
/// <c>OnDependencyValue</c> and run on the driver's own worker (Driver.Calculation-005), so a test
/// that used to assert on the very next line now settles first. Quiescence, not a sleep: the work
/// is enqueued synchronously inside the callback, so "idle" can never be observed before it lands.
/// </summary>
private static async Task Settle(CalculationDriver driver)
{
var idle = await WaitUntil(() => driver.IsEvaluationIdle, TimeSpan.FromSeconds(10));
idle.ShouldBeTrue("the calc driver's evaluation pump should have drained");
}
// ── dependency-ref extraction ─────────────────────────────────────────────────────────────
[Fact]
public void DependencyRefs_are_the_union_of_authored_tag_scripts()
{
var (driver, _, _) = Build(
CalcTag("calc/e/x", "return (double)ctx.GetTag(\"src/a\").Value + (double)ctx.GetTag(\"src/b\").Value;"),
CalcTag("calc/e/y", "return (double)ctx.GetTag(\"src/b\").Value + (double)ctx.GetTag(\"src/c\").Value;"));
driver.DependencyRefs.OrderBy(r => r).ShouldBe(new[] { "src/a", "src/b", "src/c" });
}
// ── change-gate ───────────────────────────────────────────────────────────────────────────
[Fact]
public async Task No_publish_until_every_declared_dep_has_arrived()
{
var (driver, published, _) = Build(
CalcTag("calc/e/sum", "return (double)ctx.GetTag(\"src/a\").Value + (double)ctx.GetTag(\"src/b\").Value;"));
await driver.InitializeAsync("{}", default);
// Only one of two deps arrived → the change-gate holds.
driver.OnDependencyValue("src/a", 10.0, StatusGood, DateTime.UtcNow);
await Settle(driver);
published.ShouldBeEmpty();
// Second dep arrives → now it computes + publishes 30.
driver.OnDependencyValue("src/b", 20.0, StatusGood, DateTime.UtcNow);
await Settle(driver);
published.Count.ShouldBe(1);
published.TryDequeue(out var e).ShouldBeTrue();
e!.FullReference.ShouldBe("calc/e/sum");
e.Snapshot.Value.ShouldBe(30.0);
e.Snapshot.StatusCode.ShouldBe(StatusGood);
}
/// <summary>
/// The change-gate must hold BEFORE the script ever runs, not just before the publish. A
/// multi-dependency script that casts a missing dep's <c>.Value</c> to a non-nullable type (the
/// common idiom used throughout this file) throws when evaluated against a partial snapshot, so
/// evaluating anyway during ordinary warm-up produced a spurious "script threw" script-log Warning
/// on every partial dependency arrival — even though nothing is actually wrong with the script.
/// </summary>
[Fact]
public async Task No_evaluation_or_script_log_while_a_declared_dep_is_still_missing()
{
var (driver, published, logs) = Build(
CalcTag("calc/e/sum", "return (double)ctx.GetTag(\"src/a\").Value + (double)ctx.GetTag(\"src/b\").Value;"));
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
driver.OnDependencyValue("src/a", 10.0, StatusGood, DateTime.UtcNow);
await Settle(driver);
published.ShouldBeEmpty();
logs.ShouldBeEmpty("a still-missing declared dependency must hold the gate BEFORE evaluation, " +
"not merely before the publish");
}
// ── the dependency callback must not execute scripts (Driver.Calculation-005) ─────────────
/// <summary>
/// <c>OnDependencyValue</c> is called <b>directly and synchronously</b> from
/// <c>DependencyConsumerMuxAdapter.OnDependencyValueChanged</c> — i.e. on an Akka actor's own
/// dispatcher thread. Evaluating there means a script run (bounded only by <c>RunTimeout</c>,
/// default 2 s) occupies that thread, so the callback must queue the work and return instead.
/// <para>The publish is the observable: it can only happen after the script ran, so a publish that
/// lands on the caller's stack <em>between</em> entering and leaving the callback proves the script
/// ran inline. A thread-local flag set for exactly that window is the exact test — comparing thread
/// <i>ids</i> is not, because the pump is free to reuse the pooled thread the test released while
/// waiting, which makes an id match mean nothing. The value assertion is the positive control:
/// without it this would pass just as happily against a driver that evaluates nothing at all.</para>
/// </summary>
[Fact]
public async Task A_dependency_arrival_does_not_run_the_script_on_the_callers_thread()
{
var (driver, published, _) = Build(
CalcTag("calc/e/dbl", "return (double)ctx.GetTag(\"src/a\").Value * 2.0;"));
using var insideCallback = new ThreadLocal<bool>();
var publishedInline = false;
driver.OnDataChange += (_, _) => { if (insideCallback.Value) publishedInline = true; };
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
insideCallback.Value = true;
driver.OnDependencyValue("src/a", 5.0, StatusGood, DateTime.UtcNow);
insideCallback.Value = false;
(await WaitUntil(() => !published.IsEmpty, TimeSpan.FromSeconds(10)))
.ShouldBeTrue("the queued evaluation must still compute and publish the value");
published.TryDequeue(out var e).ShouldBeTrue();
e!.Snapshot.Value.ShouldBe(10.0);
publishedInline.ShouldBeFalse(
"the calc script must run on the driver's own evaluation pump, never on the mux callback thread");
}
/// <summary>
/// The second half of Driver.Calculation-005: the evaluation also used to run <b>under the state
/// lock</b>, so a slow script froze every other lock-taking operation (here <c>ReadAsync</c>) for
/// its whole run as well as the callback itself. Both must now return while the script is still
/// executing; the trailing publish is the positive control that the script did run.
/// </summary>
[Fact]
public async Task A_slow_script_blocks_neither_the_dependency_callback_nor_a_concurrent_read()
{
// A CPU-bound busy-wait: the sandbox forbids Thread/Task, and DateTime is explicitly allowed.
const string slowScript =
"var deadline = System.DateTime.UtcNow.AddMilliseconds(600); " +
"while (System.DateTime.UtcNow < deadline) { } " +
"return (double)ctx.GetTag(\"src/a\").Value;";
var (driver, published, _) = Build(CalcTag("calc/e/slow", slowScript));
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
var elapsed = System.Diagnostics.Stopwatch.StartNew();
driver.OnDependencyValue("src/a", 7.0, StatusGood, DateTime.UtcNow);
var callbackElapsed = elapsed.Elapsed;
// ReadAsync takes the same state lock the inline evaluation used to hold for the whole run.
var snapshot = await driver.ReadAsync(["calc/e/slow"], TestContext.Current.CancellationToken);
var readElapsed = elapsed.Elapsed;
callbackElapsed.ShouldBeLessThan(TimeSpan.FromMilliseconds(300),
"the mux callback thread must not wait on the script run");
readElapsed.ShouldBeLessThan(TimeSpan.FromMilliseconds(300),
"the state lock must not be held across the script run");
snapshot[0].StatusCode.ShouldBe(StatusBadWaitingForInitialData,
"the read got through while the evaluation was still in flight");
(await WaitUntil(() => !published.IsEmpty, TimeSpan.FromSeconds(10)))
.ShouldBeTrue("the slow evaluation must still complete and publish");
published.TryDequeue(out var e).ShouldBeTrue();
e!.Snapshot.Value.ShouldBe(7.0);
await driver.ShutdownAsync(TestContext.Current.CancellationToken);
}
// ── dedup + recompute ─────────────────────────────────────────────────────────────────────
[Fact]
public async Task Equal_result_is_deduped_and_a_changed_result_republishes()
{
var (driver, published, _) = Build(
CalcTag("calc/e/dbl", "return (double)ctx.GetTag(\"src/a\").Value * 2.0;"));
await driver.InitializeAsync("{}", default);
// Each arrival is queued with the dependency snapshot that triggered it, so the three evaluations
// see 5 / 5 / 7 in that order however far the pump lags behind them.
driver.OnDependencyValue("src/a", 5.0, StatusGood, DateTime.UtcNow); // → 10 (publish)
driver.OnDependencyValue("src/a", 5.0, StatusGood, DateTime.UtcNow); // → 10 (dedup, no publish)
driver.OnDependencyValue("src/a", 7.0, StatusGood, DateTime.UtcNow); // → 14 (publish)
await Settle(driver);
published.Select(p => p.Snapshot.Value).ShouldBe(new object?[] { 10.0, 14.0 });
}
// ── Bad transition + script-log + recovery ────────────────────────────────────────────────
[Fact]
public async Task Failure_publishes_Bad_once_per_transition_emits_script_log_and_recovers()
{
var (driver, published, logs) = Build(
CalcTag("calc/e/div", "return 100 / (int)ctx.GetTag(\"src/a\").Value;"));
await driver.InitializeAsync("{}", default);
// a = 0 → DivideByZero → Failure → Bad (carrying last-known = null) + one script-log.
driver.OnDependencyValue("src/a", 0, StatusGood, DateTime.UtcNow);
await Settle(driver);
published.Count.ShouldBe(1);
published.TryDequeue(out var bad).ShouldBeTrue();
bad!.Snapshot.StatusCode.ShouldBe(StatusBadInternalError);
logs.Count.ShouldBe(1);
logs[0].Level.ShouldBe("Warning");
logs[0].ScriptId.ShouldBe("s-calc/e/div");
logs[0].VirtualTagId.ShouldBe("calc/e/div");
// a = 0 again → still failing, but NOT a fresh transition → no second Bad publish (script-log still emits).
driver.OnDependencyValue("src/a", 0, StatusGood, DateTime.UtcNow);
await Settle(driver);
published.ShouldBeEmpty();
logs.Count.ShouldBe(2);
// a = 5 → 20 → Good recovery is force-published.
driver.OnDependencyValue("src/a", 5, StatusGood, DateTime.UtcNow);
await Settle(driver);
published.Count.ShouldBe(1);
published.TryDequeue(out var good).ShouldBeTrue();
good!.Snapshot.Value.ShouldBe(20);
good.Snapshot.StatusCode.ShouldBe(StatusGood);
}
// ── timer trigger ─────────────────────────────────────────────────────────────────────────
[Fact]
public async Task Timer_only_tag_computes_on_its_interval()
{
// No dependencies (constant script) so only the timer can drive it.
var (driver, published, _) = Build(
CalcTag("calc/e/const", "return 42.0;", changeTriggered: false, timerMs: 50));
await driver.InitializeAsync("{}", default);
var fired = await WaitUntil(() => !published.IsEmpty, TimeSpan.FromSeconds(3));
fired.ShouldBeTrue("the timer trigger should have computed the tag within 3s");
published.TryDequeue(out var e).ShouldBeTrue();
e!.FullReference.ShouldBe("calc/e/const");
e.Snapshot.Value.ShouldBe(42.0);
await driver.ShutdownAsync(default);
}
// ── IReadable ─────────────────────────────────────────────────────────────────────────────
[Fact]
public async Task Read_returns_BadWaitingForInitialData_before_first_eval_then_the_computed_value()
{
var (driver, _, _) = Build(CalcTag("calc/e/x", "return (double)ctx.GetTag(\"src/a\").Value * 2.0;"));
await driver.InitializeAsync("{}", default);
var before = await driver.ReadAsync(new[] { "calc/e/x" }, default);
before[0].StatusCode.ShouldBe(StatusBadWaitingForInitialData);
driver.OnDependencyValue("src/a", 3.0, StatusGood, DateTime.UtcNow);
await Settle(driver);
var after = await driver.ReadAsync(new[] { "calc/e/x" }, default);
after[0].StatusCode.ShouldBe(StatusGood);
after[0].Value.ShouldBe(6.0);
}
// REMOVED (Gitea #517): `Health_is_always_Connected` asserted that a driver which had never been
// initialized still reported Healthy — a characterization test of the defect, not of a requirement.
// Its valid half (a running Calculation driver has no transport to be Degraded about, so it is simply
// Healthy) is covered by GetHealth_tracks_the_lifecycle_rather_than_reporting_a_constant below.
private static async Task<bool> WaitUntil(Func<bool> predicate, TimeSpan timeout)
{
var deadline = DateTime.UtcNow + timeout;
while (DateTime.UtcNow < deadline)
{
if (predicate()) return true;
await Task.Delay(20);
}
return predicate();
}
// ── health lifecycle (Gitea #517) ─────────────────────────────────────────────────────────
/// <summary>
/// Gitea #517 — <c>GetHealth()</c> must not report Healthy for a driver that is not running.
/// <para>This driver returned a hard-coded <see cref="DriverState.Healthy"/> that consulted
/// nothing, which made it the fleet's only driver reporting Healthy with its timers stopped —
/// deterministically, not as a race window. Every other driver reads a <c>_health</c> field that
/// shutdown lands on <see cref="DriverState.Unknown"/>.</para>
/// <para>The pre-initialize leg is what makes this falsifiable against the old code: a test that
/// only checked post-shutdown could be satisfied by a driver that happened to write Unknown once,
/// whereas asserting BOTH ends pins the value to the lifecycle flag.</para>
/// </summary>
[Fact]
public async Task GetHealth_tracks_the_lifecycle_rather_than_reporting_a_constant()
{
var (driver, _, _) = Build(CalcTag("calc/e/x", "return 1.0;"));
// Constructed but never initialized — nothing is computing, so Healthy would be a lie.
driver.GetHealth().State.ShouldBe(DriverState.Unknown);
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
driver.GetHealth().State.ShouldBe(DriverState.Healthy);
await driver.ShutdownAsync(TestContext.Current.CancellationToken);
driver.GetHealth().State.ShouldBe(DriverState.Unknown,
"timers are stopped and _running is false — the driver computes nothing");
// Re-initialize brings it back, so the flag is genuinely read each call rather than latched once.
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
driver.GetHealth().State.ShouldBe(DriverState.Healthy);
driver.Dispose();
driver.GetHealth().State.ShouldBe(DriverState.Unknown);
}
// ── evaluator diagnostics reach the driver's own logger ──────────────────────────────────────
/// <summary>
/// The <see cref="CalculationEvaluator"/> the driver constructs internally must log its host-side
/// diagnostics (compile errors, sandbox violations, execution throws) through the SAME
/// <c>ILogger&lt;CalculationDriver&gt;</c> the driver itself was given — not silently into a
/// no-op logger. A timer-triggered tag with a deliberately broken script is the vehicle: it
/// evaluates on its own cadence with no dependency needed to arrive first.
/// </summary>
[Fact]
public async Task Evaluator_compile_diagnostics_flow_through_to_the_drivers_own_logger()
{
var logger = new CapturingLogger();
var scriptRoot = new ScriptRootLogger(new LoggerConfiguration().CreateLogger());
var driver = new CalculationDriver(
new CalculationDriverOptions
{
RawTags = [CalcTag("calc/e/bad", "this is not valid C#;", changeTriggered: false, timerMs: 50)],
},
"calc-drv", scriptRoot, logger);
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
var fired = await WaitUntil(
() => logger.Entries.Any(e => e.Level == LogLevel.Warning && e.Message.Contains("Roslyn compile failed")),
TimeSpan.FromSeconds(3));
fired.ShouldBeTrue("the evaluator's compile-failure diagnostic should reach the driver-supplied logger");
await driver.ShutdownAsync(TestContext.Current.CancellationToken);
}
// ── skipped-tag reporting (Gitea #541) ────────────────────────────────────────────────────────
[Fact]
public async Task GetSkippedTags_reports_a_raw_tag_with_no_scriptId_alongside_the_authored_total()
{
var noScriptId = new RawTagEntry("calc/e/nogood", "{\"foo\":\"bar\"}", WriteIdempotent: false);
var good = CalcTag("calc/e/good", "return 1.0;", changeTriggered: false);
var (driver, _, _) = Build(noScriptId, good);
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
var report = driver.GetSkippedTags();
report.ShouldNotBeNull();
report!.AuthoredCount.ShouldBe(2);
report.SkippedCount.ShouldBe(1);
report.Sample.ShouldContain(s => s.RawPath == "calc/e/nogood");
}
[Fact]
public async Task GetSkippedTags_has_no_skips_when_every_authored_tag_maps()
{
var (driver, _, _) = Build(CalcTag("calc/e/good", "return 1.0;", changeTriggered: false));
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
var report = driver.GetSkippedTags();
report.ShouldNotBeNull();
report!.AuthoredCount.ShouldBe(1);
report.SkippedCount.ShouldBe(0);
report.HasSkips.ShouldBeFalse();
}
/// <summary>The skip ledger must be REBUILT on ReinitializeAsync, not just at construction — an
/// ApplyDelta that drops a tag's scriptId (or adds a new tag with none) must be reflected immediately,
/// since RebuildTagTable is the one routine both the ctor and reinit share.</summary>
[Fact]
public async Task GetSkippedTags_updates_after_reinitialize()
{
var (driver, _, _) = Build(CalcTag("calc/e/x", "return 1.0;", changeTriggered: false));
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
driver.GetSkippedTags()!.SkippedCount.ShouldBe(0);
const string reinitJson = """{"rawTags":[{"rawPath":"calc/e/x","tagConfig":"{}","writeIdempotent":false}]}""";
await driver.ReinitializeAsync(reinitJson, TestContext.Current.CancellationToken);
var report = driver.GetSkippedTags();
report!.AuthoredCount.ShouldBe(1);
report.SkippedCount.ShouldBe(1, "the reinit payload's tag has no scriptId, so it is no longer a calc tag");
}
/// <summary>Minimal capturing <see cref="ILogger{T}"/> so a test can assert on what the driver's own
/// logger received (mirrors the equivalent helper in CalculationEvaluatorTests).</summary>
private sealed class CapturingLogger : ILogger<CalculationDriver>
{
public List<(LogLevel Level, string Message)> Entries { get; } = [];
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
public bool IsEnabled(LogLevel logLevel) => true;
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception,
Func<TState, Exception?, string> formatter) =>
Entries.Add((logLevel, formatter(state, exception)));
}
private sealed class CapturingPublisher(List<ScriptLogEntry> sink) : IScriptLogPublisher
{
private readonly object _lock = new();
public void Publish(ScriptLogEntry entry)
{
lock (_lock) sink.Add(entry);
}
}
}