Files
lmxopcua/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverRemediationTests.cs
T
Joseph Doherty ef2eebe6b6 fix(scripting): review minors: configured limit in summaries, dispose gate/CTS, validator, docs (fix round 1)
- ScriptLogRateLimiter.LimitPerWindow. The ScriptLogTopicSink and
  VirtualTagActor summaries now print the configured limit, not
  DefaultLimitPerWindow. Tests assert "limit N/window" for a non-default
  N.
- CalculationDriver.Dispose cancels, then takes _evalGate (bounded 2 s)
  and disposes the gate and _evalCts. The pump and timer ticks enter the
  gate through TryEnterEvalGateAsync, which stops cleanly once the
  driver is disposed. Test: Dispose with a 6 s runaway run in flight
  returns promptly, disposes both, and a late trigger is harmless.
- ScriptedAlarmEngine captures _shutdownToken once and disposes
  _shutdownCts in Dispose when every drained task has completed. A task
  stuck past the grace leaves the CTS to the GC. Lifecycle tests assert
  the disposal.
- DraftValidator: CalculationNoEffectiveTrigger is skipped for a
  change-triggered tag whose scriptId does not resolve. That case is
  already CalculationScriptMissing or CalculationScriptNotFound, and
  there are no reads to count. Both existing tests now assert the
  absence (red before the change).
- docs/VirtualTags.md: System.Threading is denied as a whole namespace,
  with an allow-list; the type list is now accurate (Unsafe,
  RuntimeHelpers, and the ForbiddenMembers on System.Type); the resource
  limits section covers the run guard and the allocation budget.
  docs/ScriptEditor.md: accurate deny-list and a new "Runtime safety"
  section covering timeout, refusal, quarantine after 3 timeouts,
  allocation budget, lifting, and rate-limit summaries that appear only
  on the source's next entry after a burst then quiet.

Refs #734

Claude-Session: https://claude.ai/code/session_01Ub9hGmYLQvn9XETzw7CMsT
2026-10-22 13:41:15 -04:00

190 lines
9.5 KiB
C#

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