fix(runtime): restart-safe alarm host, mux last-value replay, VT log rate limit, Calculation remediation (E4)
- R02:H1 ScriptedAlarmHostActor gains a factory Props (Func<(upstream, engine)>) so every incarnation builds and owns its own engine; a supervision restart no longer re-creates the actor around a disposed engine. The legacy instance-taking Props stays source-compatible and is now restart-safe in the weaker sense (PreRestart marks the stop as a restart, PostStop then detaches instead of disposing). DriverHostActor still spawns through the legacy overload (not owned by this lane — F3). - R02:H3 OnAlarmCommand runs every engine op under a 10 s token linked to the actor's lifetime (DefaultCommandTimeout / Props commandTimeout) and logs a Warning on timeout instead of suspending the mailbox on a stalled store. - R02:L3 DependencyMuxTagUpstreamSource.RetainOnly(loaded dep-ref union), called after every successful load. - R02:P6 VirtualTagActor's per-failure ScriptLogEntry is rate-limited per tag (ScriptLogRateLimiter, 20/min + one summary); the Bad publish and the metric are untouched. - R07:H6 DependencyMuxActor retains the last (value, status, ts) per ever-registered ref (through unregisters) and replays them in one batch to a RegisterInterest(ReplayRetained: true) — VirtualTagActor, the Calculation mux adapter and the alarm host opt in; the historization recorder does not (a replay there would record a stale sample per deploy). CalculationDriver records inputs regardless of _running so a replay landing before InitializeAsync still satisfies the change-gate. - R07:P4 CalculationEvaluator negative-caches compile failures by source hash (one Roslyn attempt + one Warning per source until redeploy); the driver's script-log entry fires on the Good→Bad transition or a change of reason, matching the once-per-transition Bad publish. - R07:H8 array results dedup structurally. - R07:L2 ShutdownAsync drops the compiled scripts (collectible ALCs). - R07:U5 DraftValidator rule CalculationNoEffectiveTrigger: a tag with no timer whose change trigger is off or whose script has no literal ctx.GetTag read can never evaluate. Refs #734 Claude-Session: https://claude.ai/code/session_01Ub9hGmYLQvn9XETzw7CMsT
This commit is contained in:
Joseph Doherty
+166
@@ -0,0 +1,166 @@
|
||||
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");
|
||||
}
|
||||
|
||||
[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)));
|
||||
}
|
||||
}
|
||||
@@ -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);
|
||||
|
||||
Reference in New Issue
Block a user