dohertj2/lmxopcua
1
0
Fork 0
Code Issues 43 Pull Requests Actions Packages Projects Releases Wiki Activity

Merge local master 7bcb6331 into remed/lane-FOCAS

Browse Source 
Refs #740
Claude-Session: https://claude.ai/code/session_01Ub9hGmYLQvn9XETzw7CMsT
This commit is contained in:
Joseph Doherty
2026-10-22 14:51:26 -04:00
parent de54b23b1a 7bcb6331ed
commit 95b75c2e58
105 changed files with 10429 additions and 717 deletions
Download Patch File Download Diff File Expand all files Collapse all files
tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverRemediationTests.cs
+189
View File
@@ -0,0 +1,189 @@
using System.Collections.Concurrent;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
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>
/// Review 07 Calculation remediation: a compile failure is negative-cached by source hash and its
/// Warning/script-log fires on the Good→Bad transition only (P4); inputs are recorded before
/// <c>InitializeAsync</c> so a Restart computes from current inputs (H6); array results dedup
/// structurally (H8); <c>ShutdownAsync</c> drops the compiled scripts (L2).
/// </summary>
public sealed class CalculationDriverRemediationTests
{
private const uint StatusGood = 0u;
private const uint StatusBadInternalError = 0x80020000u;
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, CapturingLogger HostLog)
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 hostLog = new CapturingLogger();
var driver = new CalculationDriver(new CalculationDriverOptions { RawTags = tags }, "calc-drv", scriptRoot, hostLog);
var published = new ConcurrentQueue<DataChangeEventArgs>();
driver.OnDataChange += (_, e) => published.Enqueue(e);
return (driver, published, logs, hostLog);
}
private static async Task Settle(CalculationDriver driver)
{
var deadline = DateTime.UtcNow.AddSeconds(30);
while (!driver.IsEvaluationIdle && DateTime.UtcNow < deadline) await Task.Delay(10);
driver.IsEvaluationIdle.ShouldBeTrue("the calc driver's evaluation pump should have drained");
}
/// <summary>Fix round 1 minor: Dispose releases the evaluation gate and its cancellation source — even
/// with a runaway run in flight (the guard lets the caller's cancel win, so the awaited run returns
/// promptly) — and a trigger arriving after Dispose is harmless.</summary>
[Fact]
public async Task Dispose_with_a_run_in_flight_disposes_the_eval_gate_and_a_late_trigger_is_harmless()
{
var (driver, _, _, _) = Build(
CalcTag("calc/e/spin", "var v = ctx.GetTag(\"src/a\").Value; var end = System.DateTime.UtcNow.AddSeconds(6); while (System.DateTime.UtcNow < end) { } return 1;"));
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
driver.OnDependencyValue("src/a", 1, StatusGood, DateTime.UtcNow);
var deadline = DateTime.UtcNow.AddSeconds(10);
while (driver.IsEvaluationIdle && DateTime.UtcNow < deadline) await Task.Delay(5);
driver.IsEvaluationIdle.ShouldBeFalse("positive control: a run is in flight when Dispose lands");
var sw = System.Diagnostics.Stopwatch.StartNew();
driver.Dispose();
sw.Elapsed.ShouldBeLessThan(TimeSpan.FromSeconds(5), "the caller's cancel releases the awaited run; Dispose is not held for the 6 s spin");
driver.EvalResourcesDisposedForTest.ShouldBeTrue();
Should.NotThrow(() => driver.OnDependencyValue("src/a", 2, StatusGood, DateTime.UtcNow));
Should.NotThrow(() => driver.Dispose());
}
[Fact]
public async Task A_compile_failure_is_remembered_and_logged_once_across_repeated_triggers()
{
var (driver, published, logs, hostLog) = Build(
CalcTag("calc/e/broken", "var x = (double)ctx.GetTag(\"src/a\").Value; this is not valid C#;"));
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
for (var i = 0; i < 5; i++)
{
driver.OnDependencyValue("src/a", i, StatusGood, DateTime.UtcNow);
await Settle(driver);
}
published.Count.ShouldBe(1, "Bad is published once per transition");
published.TryDequeue(out var bad).ShouldBeTrue();
bad!.Snapshot.StatusCode.ShouldBe(StatusBadInternalError);
logs.Count.ShouldBe(1, "the script-log entry fires on the Good→Bad transition only");
hostLog.Entries.Count(e => e.Level == LogLevel.Warning && e.Message.Contains("compile failed")).ShouldBe(1,
"Roslyn is consulted once per source; later triggers hit the negative cache");
driver.CompileFailureCountForTest.ShouldBe(1);
}
[Fact]
public async Task A_changed_failure_reason_is_logged_even_while_already_Bad()
{
// Throws with a different message depending on the input, so the failure REASON changes while the
// published status stays Bad — the operator must see the new reason.
var (driver, published, logs, _) = Build(
CalcTag("calc/e/thrower", "throw new System.InvalidOperationException(\"boom \" + (int)ctx.GetTag(\"src/a\").Value);"));
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
driver.OnDependencyValue("src/a", 1, StatusGood, DateTime.UtcNow);
await Settle(driver);
driver.OnDependencyValue("src/a", 1, StatusGood, DateTime.UtcNow); // same reason → no new log
await Settle(driver);
driver.OnDependencyValue("src/a", 2, StatusGood, DateTime.UtcNow); // new reason → logged
await Settle(driver);
published.Count.ShouldBe(1);
logs.Count.ShouldBe(2);
logs[0].Message.ShouldContain("boom 1");
logs[1].Message.ShouldContain("boom 2");
}
[Fact]
public async Task Inputs_delivered_before_InitializeAsync_are_kept_so_the_first_trigger_computes()
{
// H6: a Restart is a new driver whose adapter registers interest at construction; the mux's
// retained-value replay therefore lands BEFORE InitializeAsync. It used to be dropped.
var (driver, published, _, _) = Build(
CalcTag("calc/e/sum", "return (double)ctx.GetTag(\"src/a\").Value + (double)ctx.GetTag(\"src/b\").Value;"));
driver.OnDependencyValue("src/a", 10.0, StatusGood, DateTime.UtcNow); // replayed, pre-init
driver.OnDependencyValue("src/b", 20.0, StatusGood, DateTime.UtcNow);
published.ShouldBeEmpty("evaluation is gated on running");
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
driver.OnDependencyValue("src/a", 12.0, StatusGood, DateTime.UtcNow); // only ONE input moves after init
await Settle(driver);
published.Count.ShouldBe(1, "src/b's pre-init value satisfied the change-gate");
published.TryDequeue(out var e).ShouldBeTrue();
e!.Snapshot.Value.ShouldBe(32.0);
}
[Fact]
public async Task An_equal_array_result_is_deduped_structurally()
{
var (driver, published, _, _) = Build(
CalcTag("calc/e/arr", "var v = (double)ctx.GetTag(\"src/a\").Value; return new double[] { v, v * 2 };"));
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
driver.OnDependencyValue("src/a", 1.0, StatusGood, DateTime.UtcNow);
await Settle(driver);
driver.OnDependencyValue("src/a", 1.0, StatusGood, DateTime.UtcNow); // same array contents
await Settle(driver);
published.Count.ShouldBe(1, "a structurally equal array is not a change");
driver.OnDependencyValue("src/a", 2.0, StatusGood, DateTime.UtcNow);
await Settle(driver);
published.Count.ShouldBe(2, "a different array still publishes");
published.Last().Snapshot.Value.ShouldBe(new double[] { 2.0, 4.0 });
}
[Fact]
public async Task ShutdownAsync_drops_the_compiled_scripts()
{
var (driver, published, _, _) = Build(CalcTag("calc/e/x", "return (double)ctx.GetTag(\"src/a\").Value * 2.0;"));
await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
driver.OnDependencyValue("src/a", 1.0, StatusGood, DateTime.UtcNow);
await Settle(driver);
published.Count.ShouldBe(1);
driver.CompiledScriptCountForTest.ShouldBe(1);
await driver.ShutdownAsync(TestContext.Current.CancellationToken);
driver.CompiledScriptCountForTest.ShouldBe(0, "the collectible ALCs must not survive the generation");
}
private sealed class CapturingPublisher(List<ScriptLogEntry> entries) : IScriptLogPublisher
{
public void Publish(ScriptLogEntry entry) { lock (entries) entries.Add(entry); }
}
internal sealed class CapturingLogger : ILogger<CalculationDriver>
{
public ConcurrentBag<(LogLevel Level, string Message)> Entries { get; } = new();
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)));
}
}
tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverTests.cs
+4 -2
View File
@@ -229,11 +229,13 @@ public sealed class CalculationDriverTests
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).
// a = 0 again → still failing for the SAME reason, NOT a fresh transition → no second Bad publish,
// and (R07:P4) no second script-log entry either: the log fires on the transition or on a change of
// reason, not on every trigger of a tag that is already Bad.
driver.OnDependencyValue("src/a", 0, StatusGood, DateTime.UtcNow);
await Settle(driver);
published.ShouldBeEmpty();
logs.Count.ShouldBe(2);
logs.Count.ShouldBe(1);
// a = 5 → 20 → Good recovery is force-published.
driver.OnDependencyValue("src/a", 5, StatusGood, DateTime.UtcNow);
tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationEvaluatorRunGuardTests.cs
+87
View File
@@ -0,0 +1,87 @@
using Microsoft.Extensions.Logging.Abstractions;
using Serilog;
using Shouldly;
using Xunit;
using ZB.MOM.WW.OtOpcUa.Core.Scripting;
namespace ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests;
/// <summary>
/// <see cref="CalculationEvaluator"/> runs every compiled script through a <see cref="ScriptRunGuard"/>
/// keyed by calc-tag RawPath. A timed-out run is abandoned on its pool thread; before the guard, every
/// later trigger of the same tag stacked another orphan behind it (one leaked thread per trigger). Now
/// every later trigger is refused ("previous evaluation still running" — Bad, but not a quarantine
/// strike; only consecutive timeouts quarantine), and a healthy sibling on the same evaluator keeps computing.
/// </summary>
public sealed class CalculationEvaluatorRunGuardTests
{
private static ScriptRootLogger NoOpScriptRoot() => new(new LoggerConfiguration().CreateLogger());
/// <summary>Outlives the 60 ms budget by a wide margin but still ends, so the orphan frees itself.</summary>
private const string SpinScript =
"var end = System.DateTime.UtcNow.AddSeconds(6); while (System.DateTime.UtcNow < end) { } return 0;";
private static readonly Dictionary<string, object?> NoDeps = new();
[Fact]
public async Task Triggers_during_the_previous_orphan_are_refused_not_quarantined_and_a_sibling_keeps_computing()
{
using var sut = new CalculationEvaluator(
NullLogger<CalculationEvaluator>.Instance, NoOpScriptRoot(), TimeSpan.FromMilliseconds(60));
var ct = TestContext.Current.CancellationToken;
var first = await sut.EvaluateAsync("calc/loop", SpinScript, Snap(NoDeps), ct).WaitAsync(TimeSpan.FromSeconds(30), ct);
first.Success.ShouldBeFalse();
first.Reason.ShouldNotBeNull();
first.Reason.ShouldContain("timed out");
// Every later trigger while the orphan runs is a Bad "previous evaluation still running" — a
// refusal is not a strike, so the tag is NOT quarantined by them (fix round 1, I1).
for (var i = 0; i < 3; i++)
{
var refused = await sut.EvaluateAsync("calc/loop", SpinScript, Snap(NoDeps), ct);
refused.Success.ShouldBeFalse();
refused.Reason.ShouldBe(ScriptRunGuard.PreviousRunStillRunningReason);
}
sut.QuarantinedScripts.ShouldBeEmpty();
sut.RunGuard.RefusedWhileRunningCount.ShouldBe(3);
// Exactly one run was ever dispatched for the runaway tag — the leak is one orphan, not one per trigger.
sut.RunGuard.StartedRunCount.ShouldBe(1);
sut.RunGuard.InFlightCount.ShouldBe(1);
// Positive control: a sibling tag on the same evaluator still computes.
var sibling = await sut.EvaluateAsync("calc/ok", "return 42;", Snap(NoDeps), ct);
sibling.Success.ShouldBeTrue(sibling.Reason);
sibling.Value.ShouldBe(42);
}
[Fact]
public async Task ClearCompiledScripts_lifts_the_quarantine_as_a_redeploy_does()
{
using var sut = new CalculationEvaluator(
NullLogger<CalculationEvaluator>.Instance, NoOpScriptRoot(), TimeSpan.FromMilliseconds(60),
new ScriptingOptions { QuarantineAfterConsecutiveTimeouts = 1 });
var ct = TestContext.Current.CancellationToken;
var r = await sut.EvaluateAsync("calc/loop", SpinScript, Snap(NoDeps), ct).WaitAsync(TimeSpan.FromSeconds(30), ct);
r.Reason.ShouldNotBeNull();
r.Reason.ShouldStartWith(ScriptRunGuard.QuarantinedReasonPrefix);
sut.ClearCompiledScripts();
sut.QuarantinedScripts.ShouldBeEmpty();
// The fixed script (new source) runs; the old orphan is a sunk cost that no longer blocks the tag.
var fixedRun = await sut.EvaluateAsync("calc/loop", "return 7;", Snap(NoDeps), ct);
fixedRun.Success.ShouldBeTrue(fixedRun.Reason);
fixedRun.Value.ShouldBe(7);
}
private static Dictionary<string, Core.Abstractions.DataValueSnapshot> Snap(Dictionary<string, object?> deps)
{
var now = DateTime.UtcNow;
var d = new Dictionary<string, Core.Abstractions.DataValueSnapshot>(StringComparer.Ordinal);
foreach (var kv in deps) d[kv.Key] = new Core.Abstractions.DataValueSnapshot(kv.Value, 0u, now, now);
return d;
}
}