Joseph Doherty
a836e0d983
Code review of Driver.Calculation found two real defects, both TDD-fixed:
- CalculationDriver's ctor tried to reuse its ILogger<CalculationDriver> as the
evaluator's ILogger<CalculationEvaluator> via an `is` check that can never
succeed (unrelated closed generics), so CalculationEvaluator always ran with
a NullLogger regardless of what the driver was constructed with. Fixed by
having CalculationEvaluator accept the non-generic ILogger instead.
- EvaluateTag called the evaluator BEFORE checking whether every declared
dependency had arrived, so a multi-dependency change-triggered calc tag
evaluated its script against a partial snapshot on every warm-up tick.
VirtualTagContext.GetTag returns a Bad snapshot (.Value == null) for a
missing dep, so the idiomatic `(double)ctx.GetTag("x").Value` cast throws
NullReferenceException — caught and logged as a spurious "script threw"
script-log Warning on ordinary deploy/restart warm-up, for the standard
multi-input calc-tag shape. Fixed by gating evaluation itself on
"all deps arrived", not just the publish.
See code-reviews/Driver.Calculation/findings.md for full detail (5 findings:
001-004 Resolved, 005 Open/cross-module).
339 lines
17 KiB
C#
339 lines
17 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);
|
|
}
|
|
|
|
// ── 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);
|
|
published.ShouldBeEmpty();
|
|
|
|
// Second dep arrives → now it computes + publishes 30.
|
|
driver.OnDependencyValue("src/b", 20.0, StatusGood, DateTime.UtcNow);
|
|
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);
|
|
|
|
published.ShouldBeEmpty();
|
|
logs.ShouldBeEmpty("a still-missing declared dependency must hold the gate BEFORE evaluation, " +
|
|
"not merely before the publish");
|
|
}
|
|
|
|
// ── 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);
|
|
|
|
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)
|
|
|
|
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);
|
|
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);
|
|
published.ShouldBeEmpty();
|
|
logs.Count.ShouldBe(2);
|
|
|
|
// a = 5 → 20 → Good recovery is force-published.
|
|
driver.OnDependencyValue("src/a", 5, StatusGood, DateTime.UtcNow);
|
|
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);
|
|
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<CalculationDriver></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);
|
|
}
|
|
}
|
|
}
|