Merge #843 #840 #841 load flakes, ScriptRunGuard slot-release race, DurationGood conformance, CI QuestDB pin
v2-ci / unit-tests (push) Failing after 1h12m19s

This commit is contained in:
Joseph Doherty
2026-11-11 05:10:00 -05:00
8 changed files with 272 additions and 51 deletions
+9 -1
View File
@@ -70,7 +70,15 @@ Neither touches `v2-ci.yml`; each has its own concurrency group (`lmxopcua-v2-in
QuestDB and opc-plc — plus a port-NAT opc-plc (`otopcua-ci-opcplc-nat`, host 50110 → 50000, private `.invalid`
advertised host, `OPCUA_NAT_ENDPOINT`, #813) — (`otopcua-ci-*`, non-default host ports), exports the env vars the fixtures read, and
`down` removes them. It uses plain `docker run`, not `services:` (act_runner support is undocumented and
Postgres needs a seed step); the only runner requirement is a docker daemon. Runs the Sql, Historian.SqlServer,
Postgres needs a seed step); the only runner requirement is a docker daemon.
**QuestDB is a throwaway container by decision (#841), not the shared `/opt/otopcua-questdb` fixture (#822):** CI stays
hermetic — no dependency on the 10.100.0.35 box, no state left by a developer's runs, nothing a concurrent CI job can
share. What must not differ is the engine, so `integration-fixtures.sh` reads the image tag from the shared fixture's
compose file (`tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Historian.QuestDb.IntegrationTests/Docker/docker-compose.yml`,
currently `questdb/questdb:10.0.1`, the same pin as `docker-dev/docker-compose.questdb.yml`) instead of hard-coding
one, and fails `up` if that line is missing. Upgrade QuestDB by bumping the compose file (and the docker-dev overlay);
`CI_QDB_IMAGE` overrides the image for a one-off trial. Both run QuestDB's defaults (incl.
`cairo.ttl.use.wall.clock=true`, which the historian relies on). Runs the Sql, Historian.SqlServer,
Historian.QuestDb, OpcUaClient and OpcUaClient.Browser `*.IntegrationTests` with `MIN_EXECUTED=440`.
Local run: 468 executed / 8 skipped (Oracle x2, the blackhole `docker pause` gate, one QuestDB stress test,
4 others), about 4.5 min of test time, QuestDB the longest (~3.3 min). Not covered (no pullable image or
+14 -1
View File
@@ -29,6 +29,18 @@ SA_PASSWORD="${CI_SA_PASSWORD:-Ci_throwaway_Pw1}"
PG_PASSWORD="${CI_PG_PASSWORD:-Ci_throwaway_pg1}"
NAMES=(otopcua-ci-mssql otopcua-ci-pg otopcua-ci-questdb otopcua-ci-opcplc otopcua-ci-opcplc-nat)
ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/../.." && pwd)"
# #841: CI keeps its OWN throwaway QuestDB (hermetic — never the shared /opt/otopcua-questdb fixture), but runs the
# SAME image the shared fixture's compose file pins, read from that file so the two cannot drift. CI_QDB_IMAGE
# overrides it only to trial an upgrade.
QDB_COMPOSE="$ROOT/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Historian.QuestDb.IntegrationTests/Docker/docker-compose.yml"
questdb_image() {
if [ -n "${CI_QDB_IMAGE:-}" ]; then echo "$CI_QDB_IMAGE"; return; fi
local img
img="$(sed -n 's/^[[:space:]]*image:[[:space:]]*\(questdb\/questdb:[^[:space:]]*\).*/\1/p' "$QDB_COMPOSE" | head -n 1)"
if [ -z "$img" ]; then echo "no questdb/questdb:<tag> image line in $QDB_COMPOSE" >&2; return 1; fi
echo "$img"
}
fixture_host() {
if [ -n "${FIXTURE_HOST:-}" ]; then echo "$FIXTURE_HOST"; return; fi
@@ -52,6 +64,7 @@ wait_for() { # <description> <timeout-seconds> <command...>
up() {
command -v docker >/dev/null || { echo "docker not available" >&2; exit 1; }
local qdb_image; qdb_image="$(questdb_image)"
down
docker run -d --name otopcua-ci-mssql -e ACCEPT_EULA=Y -e MSSQL_PID=Developer \
-e "MSSQL_SA_PASSWORD=$SA_PASSWORD" -p "$SQL_PORT:1433" \
@@ -59,7 +72,7 @@ up() {
docker run -d --name otopcua-ci-pg -e "POSTGRES_PASSWORD=$PG_PASSWORD" -e POSTGRES_DB=sqlpollfixture \
-p "$PG_PORT:5432" postgres:17-alpine >/dev/null
docker run -d --name otopcua-ci-questdb -p "$QDB_PORT:8812" -p "$QDB_HTTP_PORT:9000" \
questdb/questdb:10.0.1 >/dev/null
"$qdb_image" >/dev/null
docker run -d --name otopcua-ci-opcplc -p "$OPC_PORT:$OPC_PORT" \
mcr.microsoft.com/iotedge/opc-plc:2.14.10 --pn="$OPC_PORT" --ut --aa --alm >/dev/null
# Mirrors tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.OpcUaClient.IntegrationTests/Docker/nat/docker-compose.yml.
@@ -105,6 +105,13 @@ public sealed class ScriptRunGuard
_logger = logger ?? Log.Logger;
}
/// <summary>
/// Test seam (lmxopcua#843): invoked on the run's own thread just before its slot is released, with the key.
/// A sleep here widens the release window, so a test can prove the release is ordered before the caller
/// resumes rather than winning a race.
/// </summary>
internal Action<string>? SlotReleasingForTest { get; set; }
/// <summary>Raised (on the thread that detected it) when a script is quarantined.</summary>
public event EventHandler<ScriptQuarantinedEventArgs>? Quarantined;
@@ -233,34 +240,46 @@ public sealed class ScriptRunGuard
Volatile.Write(ref state.RunStartedTimestamp, Stopwatch.GetTimestamp());
started.TrySetResult();
var before = GC.GetAllocatedBytesForCurrentThread();
var succeeded = false;
try
{
// ScriptEvaluator.RunAsync executes the compiled delegate synchronously and returns a completed
// task, so the after-sample is taken on the same thread, right after the script returned.
var pending = evaluator.RunAsync(context, runToken);
slot.AllocatedBytes = GC.GetAllocatedBytesForCurrentThread() - before;
return await pending.ConfigureAwait(false);
var value = await pending.ConfigureAwait(false);
succeeded = true;
return value;
}
catch
{
slot.AllocatedBytes = GC.GetAllocatedBytesForCurrentThread() - before;
throw;
}
finally
{
// Release the slot when the run REALLY finishes — which for an abandoned run is long after
// RunAsync has thrown ScriptTimeoutException — and BEFORE runTask completes (lmxopcua#843). This
// used to be a ContinueWith on runTask: a task is observably complete before its continuations
// run, so a caller that saw the completion (e.g. the virtual-tag evaluator's immediate retry after a
// raced ObjectDisposedException, or simply the next trigger) could
// start the key's NEXT run while this one still held the slot and be refused "previous
// evaluation still running" — a Bad publish for a script that had finished. Seen under load:
// 24 of 4,800 sequential same-key evaluations. A late-finishing orphan that breached the
// allocation budget quarantines its key first, so no re-trigger slips in between.
if (succeeded && BreachedBudget(slot.AllocatedBytes))
Quarantine(key, state, AllocationReason(slot.AllocatedBytes), "allocation");
SlotReleasingForTest?.Invoke(key);
Volatile.Write(ref state.RunStartedTimestamp, 0);
Interlocked.Exchange(ref state.InFlight, 0);
Interlocked.Decrement(ref _inFlight);
}
});
// Release the slot when the run REALLY finishes — which for an abandoned run is long after this
// method has thrown ScriptTimeoutException. Registered before the wait so it fires regardless of
// which way the wait below comes out. A late-finishing orphan that breached the allocation budget
// still quarantines its key here.
_ = runTask.ContinueWith(t =>
{
Volatile.Write(ref state.RunStartedTimestamp, 0);
Interlocked.Exchange(ref state.InFlight, 0);
Interlocked.Decrement(ref _inFlight);
runCts.Dispose();
if (t.IsFaulted) _ = t.Exception; // observed below by the awaiter when it is still listening
if (t.IsCompletedSuccessfully && BreachedBudget(slot.AllocatedBytes))
Quarantine(key, state, AllocationReason(slot.AllocatedBytes), "allocation");
}, CancellationToken.None, TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default);
// The budget clock starts when the pool starts the run, not when we queued it (P5): pool starvation
@@ -313,7 +332,7 @@ public sealed class ScriptRunGuard
&& !string.Equals(state.SourceIdentity, sourceIdentity, StringComparison.Ordinal))
{
// The script changed under this key: start from a clean slate. The old state's orphan (if any)
// releases the GLOBAL in-flight count through its own continuation; nothing else references it.
// releases the GLOBAL in-flight count when it finishes; nothing else references it.
_keys.TryUpdate(key, new KeyState(sourceIdentity), state);
continue;
}
@@ -61,6 +61,40 @@ public sealed class ScriptRunGuardTests
guard.IsQuarantined("vt-1", out _).ShouldBeFalse();
}
/// <summary>
/// lmxopcua#843: a caller that awaited its run is never refused by it. The slot used to be released by a
/// ContinueWith on the run task — and a task is observably complete before its continuations run, so the
/// caller (or the evaluator's immediate ODE retry) could start the key's next run while the finished one still
/// held the slot: "previous evaluation still running", 24 of 4,800 sequential evaluations in the Host
/// integration suite under load. The second phase makes every release slow (the hook sleeps inside it), so
/// the ordering, not luck, is what keeps the caller from being refused. Mutation check: release from a
/// continuation again and the second phase goes red.
/// </summary>
[Fact]
public async Task A_caller_that_awaited_its_run_is_never_refused_by_it()
{
var guard = new ScriptRunGuard();
using var fast = Compile(FastScript);
var ct = TestContext.Current.CancellationToken;
var refused = new List<string>();
for (var i = 0; i < 500; i++)
{
try { (await Run(guard, "seq", FastScript, fast, ct: ct)).ShouldBe(42); }
catch (ScriptRunRefusedException) { refused.Add($"#{i}"); }
}
refused.ShouldBeEmpty();
guard.SlotReleasingForTest = _ => Thread.Sleep(5);
for (var i = 0; i < 50; i++)
{
try { (await Run(guard, "seq", FastScript, fast, ct: ct)).ShouldBe(42); }
catch (ScriptRunRefusedException) { refused.Add($"slow release #{i}"); }
}
refused.ShouldBeEmpty();
guard.RefusedWhileRunningCount.ShouldBe(0);
guard.InFlightCount.ShouldBe(0);
}
[Fact]
public async Task A_timed_out_run_throws_ScriptTimeoutException_and_keeps_the_slot_held_by_the_orphan()
{
@@ -162,7 +196,7 @@ public sealed class ScriptRunGuardTests
/// <c>while(true)</c> script on a 1 Hz trigger leaked one pool thread per trigger — 30 orphans after 30
/// triggers, trending toward pool starvation. Now the first trigger's orphan is the only one; later
/// triggers are refused while it is young, and once it has run longer than
/// <see cref="ScriptingOptions.StuckOrphanQuarantineFactor"/> × the timeout (10 × 60 ms here — the
/// <see cref="ScriptingOptions.StuckOrphanQuarantineFactor"/> × the timeout (50 × 60 ms here — the
/// trigger cadence is scaled down from 1 Hz to keep the test short) the next refusal quarantines it.
/// A healthy sibling keeps evaluating throughout (the positive control an absence assertion needs).
/// </summary>
@@ -171,44 +205,79 @@ public sealed class ScriptRunGuardTests
/// / <see cref="ScriptRunGuard.StartedRunCount"/>): <see cref="ThreadPool.ThreadCount"/> moves with
/// every parallel test class on a loaded machine, so it is kept as a coarse secondary check only —
/// it must stay far below the 30 the leak would have produced.
/// <para>lmxopcua#843 (failed 2/4 full-suite runs at load average 140–280; 2 of the first 4 runs alone under
/// 28 CPU burners): this used to label a refusal "young" by the TEST's stopwatch, started before the first
/// trigger, and demand one inside 600 ms (10 × 60 ms). Under load the first trigger's dispatch, the sibling
/// and the cadence ate those 600 ms, so the guard's answers were <c>timeout, refused, refused,
/// quarantined…</c> — the guard right, the test's label wrong. Now: the guard is the authority on the
/// orphan's age (a <see cref="ScriptRunRefusedException"/> IS the young-orphan answer; behind a stuck one
/// it quarantines instead), the stuck factor is 50 (3 s) so the second trigger has ample room to land
/// while the orphan is young, the loop runs until the quarantine instead of a fixed 30 triggers, and the
/// one wall-clock check left runs the safe way round — the orphan is never older than the test's
/// stopwatch, so a quarantine before 3 s on it is early on any box. The runaway is a HELD spin (released
/// at the end) so it cannot end on its own and become a second dispatch on a slow box.</para>
/// </remarks>
[Fact]
public async Task Runaway_script_leaves_one_orphan_is_quarantined_once_stuck_and_a_sibling_keeps_evaluating()
{
var guard = new ScriptRunGuard();
using var spin = Compile(SpinScript);
const double stuckFactor = 50;
var guard = new ScriptRunGuard(new ScriptingOptions { StuckOrphanQuarantineFactor = stuckFactor });
using var spin = Compile(BriefSpinScript);
using var fast = Compile(FastScript);
var ct = TestContext.Current.CancellationToken;
var held = new FakeScriptContext();
var threadsBefore = ThreadPool.ThreadCount;
var stuckAfter = ShortTimeout * ScriptingOptions.DefaultStuckOrphanQuarantineFactor; // 600 ms
var stuckAfter = ShortTimeout * stuckFactor; // 3 s
var healthyResults = new List<int>();
var outcomes = new List<string>();
var timeline = new List<string>();
TimeSpan? quarantinedAt = null;
var sw = System.Diagnostics.Stopwatch.StartNew();
for (var trigger = 0; trigger < 30; trigger++)
try
{
try { await Run(guard, "runaway", SpinScript, spin, ShortTimeout, ct); outcomes.Add("value"); }
catch (ScriptTimeoutException) { outcomes.Add("timeout"); }
catch (ScriptRunRefusedException) { outcomes.Add(sw.Elapsed < stuckAfter ? "refused-young" : "refused"); }
catch (ScriptQuarantinedException) { outcomes.Add("quarantined"); }
// At least 30 triggers (the leak's scale), then until three quarantined answers; capped as a hang guard.
for (var trigger = 0; trigger < 1_000 && (trigger < 30 || outcomes.Count(o => o == "quarantined") < 3); trigger++)
{
string outcome;
try { await Run(guard, "runaway", BriefSpinScript, spin, ShortTimeout, ct, held); outcome = "value"; }
catch (ScriptTimeoutException) { outcome = "timeout"; }
catch (ScriptRunRefusedException) { outcome = "refused"; }
catch (ScriptQuarantinedException) { outcome = "quarantined"; quarantinedAt ??= sw.Elapsed; }
outcomes.Add(outcome);
timeline.Add($"#{trigger} {outcome} @{sw.ElapsedMilliseconds}ms");
healthyResults.Add(await Run(guard, "healthy", FastScript, fast, ct: ct));
await Task.Delay(50, ct);
healthyResults.Add(await Run(guard, "healthy", FastScript, fast, ct: ct));
await Task.Delay(50, ct);
}
var triggers = outcomes.Count;
var diagnostics = $"timeline: {string.Join(", ", timeline)}";
guard.InFlightCount.ShouldBe(1, "exactly one orphaned run — the first trigger's — may be executing; " + diagnostics);
guard.StartedRunCount.ShouldBe(1 + triggers, "one dispatch for the runaway script, one per trigger for the healthy sibling; " + diagnostics);
outcomes[0].ShouldBe("timeout", diagnostics);
var firstQuarantine = outcomes.IndexOf("quarantined");
firstQuarantine.ShouldBeGreaterThan(0, "the stuck orphan was never quarantined; " + diagnostics);
outcomes.Take(firstQuarantine).Skip(1).ShouldAllBe(o => o == "refused", diagnostics);
outcomes.Take(firstQuarantine).ShouldContain("refused",
"a young orphan is only refused — a short overrun is not quarantined; " + diagnostics);
outcomes.Skip(firstQuarantine).ShouldAllBe(o => o == "quarantined", diagnostics);
quarantinedAt!.Value.ShouldBeGreaterThanOrEqualTo(stuckAfter,
$"the orphan is never older than the test's stopwatch, so a quarantine before {stuckFactor}x the budget on it is early; " + diagnostics);
guard.IsQuarantined("runaway", out var reason).ShouldBeTrue("the orphan outlived its stuck threshold");
reason!.ShouldContain("stuck");
guard.QuarantinedCount.ShouldBe(1);
healthyResults.ShouldAllBe(v => v == 42);
healthyResults.Count.ShouldBe(triggers);
var threadDelta = ThreadPool.ThreadCount - threadsBefore;
threadDelta.ShouldBeLessThan(15, $"{triggers} leaked orphans would have grown the pool by ~{triggers} threads");
}
guard.InFlightCount.ShouldBe(1, "exactly one orphaned run — the first trigger's — may be executing");
guard.StartedRunCount.ShouldBe(1 + 30, "one dispatch for the runaway script, thirty for the healthy sibling");
outcomes[0].ShouldBe("timeout");
outcomes.ShouldContain("refused-young", "a young orphan is only refused — a short overrun is not quarantined");
guard.IsQuarantined("runaway", out var reason).ShouldBeTrue("the orphan outlived 10x its budget: it is stuck");
reason!.ShouldContain("stuck");
outcomes[^1].ShouldBe("quarantined");
guard.QuarantinedCount.ShouldBe(1);
healthyResults.ShouldAllBe(v => v == 42);
healthyResults.Count.ShouldBe(30);
var threadDelta = ThreadPool.ThreadCount - threadsBefore;
threadDelta.ShouldBeLessThan(15, "thirty leaked orphans would have grown the pool by ~30 threads");
finally
{
held.Released = true;
}
await WaitForIdle(guard);
}
/// <summary>
@@ -127,6 +127,27 @@ public abstract class ProcessedConformance : ConformanceBase
s.Select(x => x.StatusCode).ShouldBe([GoodCalc, GoodCalc, GoodCalc | 0x4u, NoDataCalc]);
}
[Theory]
[InlineData(HistoryAggregateType.DurationGood, 20_000d, 10_000d, 20_000d)]
[InlineData(HistoryAggregateType.DurationBad, 0d, 10_000d, 0d)]
public async Task Duration_aggregates_are_the_region_times_in_milliseconds(HistoryAggregateType agg, double b0, double b1,
double b2)
{
// #820/#840 (Part 13 §5.4.3.31/32): the same stepped regions as the percentages above, as an OPC UA Duration (ms) —
// B1: [20,30) Bad = 10 000 ms, [30,40) Good = 10 000 ms; B2 runs from the last sample (+40) to the interval end,
// Partial; B3 is after the end of the data ⇒ BadNoData. Same statuses as PercentGood/PercentBad.
await ConformanceData.SeedAAsync(B);
var s = (await ReadA(agg)).Samples;
s.Select(x => x.Value).ShouldBe([b0, b1, b2, null]);
s.Select(x => x.StatusCode).ShouldBe([GoodCalc, GoodCalc, GoodCalc | Partial, NoDataCalc]);
s.Select(x => x.SourceTimestampUtc).ShouldBe([B.Round(At(0)), B.Round(At(20)), B.Round(At(40)), B.Round(At(60))]);
// Duration = Percent × interval ÷ 100, interval by interval (one oracle for both families).
var percent = (await ReadA(agg == HistoryAggregateType.DurationGood
? HistoryAggregateType.PercentGood : HistoryAggregateType.PercentBad)).Samples;
for (var i = 0; i < 3; i++)
((double)s[i].Value!).ShouldBe((double)percent[i].Value! * Twenty.TotalMilliseconds / 100, 1e-9, $"bucket {i}");
}
[Fact]
public async Task Actual_time_aggregates_stamp_the_sample_time()
{
@@ -415,6 +436,7 @@ public abstract class ProcessedConformance : ConformanceBase
HistoryAggregateType.Range, HistoryAggregateType.Start, HistoryAggregateType.End,
HistoryAggregateType.Delta, HistoryAggregateType.MinimumActualTime, HistoryAggregateType.MaximumActualTime,
HistoryAggregateType.PercentGood, HistoryAggregateType.PercentBad,
HistoryAggregateType.DurationGood, HistoryAggregateType.DurationBad, // #820/#840
})
{
var ours = (await src.ReadProcessedAsync("P", At(from), At(to), interval, agg, Ct)).Samples.ToList();
@@ -481,6 +503,9 @@ public abstract class ProcessedConformance : ConformanceBase
(await One(HistoryAggregateType.Start)).Value.ShouldBe(10d);
// #680: duration-based — [0,5) Good, [5,10) Bad, [10,20) Good (no end bound: the last region runs to the interval end).
((double)(await One(HistoryAggregateType.PercentBad)).Value!).ShouldBe(25d, 1e-9);
// #840: the same regions in ms — [5,10) Bad = 5 000, [0,5) + [10,20) Good = 15 000.
((double)(await One(HistoryAggregateType.DurationBad)).Value!).ShouldBe(5_000d, 1e-9);
((double)(await One(HistoryAggregateType.DurationGood)).Value!).ShouldBe(15_000d, 1e-9);
}
[Fact]
@@ -507,6 +532,11 @@ public abstract class ProcessedConformance : ConformanceBase
pb.Value.ShouldBe(100d);
// The tag's data starts (+1) inside the interval ⇒ Partial on the non-Bad percentage (#677).
pb.StatusCode.ShouldBe(GoodCalc | 0x4u);
// #840: DurationBad is the same statement in ms — the whole 20 s interval — with the same status.
var db = await One(HistoryAggregateType.DurationBad);
db.Value.ShouldBe(20_000d);
db.StatusCode.ShouldBe(GoodCalc | 0x4u);
(await One(HistoryAggregateType.DurationGood)).Value.ShouldBe(0d);
}
[Fact]
@@ -662,6 +692,7 @@ public abstract class ProcessedConformance : ConformanceBase
(await One(HistoryAggregateType.Start)).Value.ShouldBe("a");
(await One(HistoryAggregateType.End)).Value.ShouldBe("b");
(await One(HistoryAggregateType.PercentGood)).Value.ShouldBe(100d);
(await One(HistoryAggregateType.DurationGood)).Value.ShouldBe(20_000d); // #840: quality, not value — strings too
foreach (var a in new[]
{
HistoryAggregateType.Average, HistoryAggregateType.Minimum, HistoryAggregateType.Maximum,
@@ -845,6 +876,11 @@ public abstract class ProcessedConformance : ConformanceBase
// #680: PercentGood/PercentBad are duration-based, served by the same window stream ⇒ capped too.
(await Should.ThrowAsync<HistoryReadLimitExceededException>(
() => under.ReadProcessedAsync("A", At(0), At(80), Twenty, HistoryAggregateType.PercentGood, Ct))).Limit.ShouldBe(4);
// #820/#840: DurationGood/DurationBad ride the same window stream ⇒ capped too.
(await Should.ThrowAsync<HistoryReadLimitExceededException>(
() => under.ReadProcessedAsync("A", At(0), At(80), Twenty, HistoryAggregateType.DurationGood, Ct))).Limit.ShouldBe(4);
(await Should.ThrowAsync<HistoryReadLimitExceededException>(
() => under.ReadProcessedAsync("A", At(0), At(80), Twenty, HistoryAggregateType.DurationBad, Ct))).Limit.ShouldBe(4);
// Pushed-down (per-sample) aggregates are not capped; the bound rows outside the window do not count.
(await under.ReadProcessedAsync("A", At(0), At(80), Twenty, HistoryAggregateType.Average, Ct)).Samples.Count.ShouldBe(4);
(await B.CreateDataSource(3).ReadProcessedAsync("W", At(0), At(80), Twenty, HistoryAggregateType.TimeAverage, Ct))
@@ -85,7 +85,7 @@ public sealed class EquipmentNamespaceMaterializationTests
return true;
}
return false;
}, TwoNodeClusterHarness.DeploySealTimeout);
}, TwoNodeClusterHarness.DeploySealTimeout, () => DescribeDeploymentAsync(harness, deploymentId));
var composition = DeploymentArtifact.ParseComposition(artifact);
@@ -182,7 +182,7 @@ public sealed class EquipmentNamespaceMaterializationTests
return true;
}
return false;
}, TwoNodeClusterHarness.DeploySealTimeout);
}, TwoNodeClusterHarness.DeploySealTimeout, () => DescribeDeploymentAsync(harness, deploymentId));
await using (var db = await CreateDbAsync(harness))
{
@@ -261,7 +261,8 @@ public sealed class EquipmentNamespaceMaterializationTests
return await factory.CreateDbContextAsync();
}
private static async Task WaitForAsync(Func<Task<bool>> condition, TimeSpan timeout)
private static async Task WaitForAsync(Func<Task<bool>> condition, TimeSpan timeout,
Func<Task<string>>? diagnose = null)
{
var deadline = DateTime.UtcNow + timeout;
while (DateTime.UtcNow < deadline)
@@ -269,6 +270,29 @@ public sealed class EquipmentNamespaceMaterializationTests
if (await condition()) return;
await Task.Delay(200);
}
throw new TimeoutException($"Condition not met within {timeout}");
throw new TimeoutException($"Condition not met within {timeout}"
+ (diagnose is null ? "" : $"; state at timeout: {await diagnose()}"));
}
/// <summary>
/// lmxopcua#843: the seal wait used to time out with a bare "Condition not met within 45s" (seen once at load
/// average 140–280, 48 s against a normal 3 s). Report where the deploy stood — the deployment row, each node's
/// per-node state, and both nodes' cluster views — so the next failure says whether it was a slow apply, a node
/// that never received the dispatch (no ack, still Applying), or a failed apply.
/// </summary>
private static async Task<string> DescribeDeploymentAsync(TwoNodeClusterHarness harness, Guid deploymentId)
{
await using var db = await CreateDbAsync(harness);
var d = await db.Deployments.AsNoTracking().FirstOrDefaultAsync(x => x.DeploymentId == deploymentId);
var nodes = await db.NodeDeploymentStates.AsNoTracking()
.Where(s => s.DeploymentId == deploymentId).ToListAsync();
static string View(Akka.Actor.ActorSystem s) => string.Join(",",
Akka.Cluster.Cluster.Get(s).State.Members.Select(m => $"{m.Address.Port}:{m.Status}"))
+ $" unreachable={Akka.Cluster.Cluster.Get(s).State.Unreachable.Count}";
return $"deployment={d?.Status.ToString() ?? "<missing>"} artifact={d?.ArtifactBlob.Length ?? 0}B "
+ $"failure='{d?.FailureReason}' created={d?.CreatedAtUtc:O} now={DateTime.UtcNow:O}; "
+ $"nodes=[{string.Join("; ", nodes.Select(n => $"{n.NodeId} {n.Status} started={n.StartedAtUtc:O} applied={n.AppliedAtUtc:O} failure='{n.FailureReason}'"))}] "
+ $"(expected {harness.NodeANodeId}, {harness.NodeBNodeId}); "
+ $"A view=[{View(harness.NodeASystem)}] B view=[{View(harness.NodeBSystem)}]";
}
}
@@ -466,6 +466,19 @@ public sealed class RoslynVirtualTagEvaluatorTests
/// for the same reason: a handful of queued-too-long evaluations is the environment, but 10% of them
/// missing a 5 s budget means the evaluator stopped evaluating. If a loaded box ever does trip EITHER
/// bound, the rate itself is the finding: record it before widening the number.</para></summary>
/// <remarks>
/// <b>lmxopcua#843 — this test found a product bug, not a timing assumption.</b> Under the full Host
/// integration suite plus 28 CPU burners (load ~300) it failed 1 run in 3 with 24 of 4,800 evaluations
/// refused <c>"previous evaluation still running"</c> — impossible for one sequential loop per id unless the
/// id's previous run still held its <see cref="ScriptRunGuard"/> slot after its caller had resumed. It did:
/// the slot was released by a continuation on the run task, and a task is observably complete before its
/// continuations run (worst for the evaluator's immediate retry after a raced
/// <see cref="ObjectDisposedException"/>). The release now happens inside the run, before it completes
/// (<c>ScriptRunGuardTests.A_caller_that_awaited_its_run_is_never_refused_by_it</c> pins the ordering). A
/// refusal stays in the "leaked" bucket on purpose. The doc above predates P5: the guard's budget clock
/// starts when the pool starts the run, so a queued evaluation no longer lands in the timed-out bucket.
/// Every assertion now prints the run's shape (elapsed, evaluations, clears, pool state, failure histogram).
/// </remarks>
[Fact]
public async Task Evaluate_racing_ClearCompiledScripts_never_leaks_a_raw_disposed_failure()
{
@@ -511,19 +524,37 @@ public sealed class RoslynVirtualTagEvaluatorTests
Interlocked.Decrement(ref remaining);
}, TestContext.Current.CancellationToken)).ToArray();
var clears = 0L;
var clearLoop = Task.Run(() =>
{
while (Volatile.Read(ref remaining) > 0)
{
sut.ClearCompiledScripts();
Interlocked.Increment(ref clears);
Thread.SpinWait(4000); // ~tens of µs between clears — frequent, but not back-to-back
}
}, TestContext.Current.CancellationToken);
// lmxopcua#843: every assertion below carries the run's shape, so a failure under load says which bucket
// moved and how starved the box was (it passed 5/5 on rerun with nothing recorded).
var elapsed = System.Diagnostics.Stopwatch.StartNew();
string Diagnostics() =>
$" [elapsed {elapsed.ElapsedMilliseconds} ms, {Volatile.Read(ref evaluated)} evaluations, " +
$"{Interlocked.Read(ref clears)} clears, loops still running {Volatile.Read(ref remaining)}, " +
$"pool threads {ThreadPool.ThreadCount} / pending {ThreadPool.PendingWorkItemCount}; failures: " +
string.Join(", ", failures.GroupBy(r => r.Length > 80 ? r[..80] : r).Select(g => $"{g.Count()}× \"{g.Key}\"")) + "]";
// Hang detector only: the loops self-terminate at RaceWindow, so firing this means something
// wedged, not that the box was slow.
await Task.WhenAll(evalLoops.Append(clearLoop))
.WaitAsync(TimeSpan.FromSeconds(45), TestContext.Current.CancellationToken);
try
{
await Task.WhenAll(evalLoops.Append(clearLoop))
.WaitAsync(TimeSpan.FromSeconds(45), TestContext.Current.CancellationToken);
}
catch (TimeoutException ex)
{
throw new TimeoutException("the racing loops did not finish within 45 s" + Diagnostics(), ex);
}
var totalEvaluations = Volatile.Read(ref evaluated);
// Loose by design, with an absolute floor so a starved run (few evaluations landed) cannot trip on
@@ -544,20 +575,20 @@ public sealed class RoslynVirtualTagEvaluatorTests
leaked.ShouldBeEmpty(
"a racing ClearCompiledScripts must never surface a failure other than " +
$"\"{ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation}\" or " +
$"\"{ScriptEvalFailureReasons.TimedOutPrefix}…\"; observed: {string.Join(" | ", leaked)}");
$"\"{ScriptEvalFailureReasons.TimedOutPrefix}…\"; observed: {string.Join(" | ", leaked)}" + Diagnostics());
// (2) Non-vacuity: the retry must actually be absorbing the race, not merely relabelling it.
exhausted.ShouldBeLessThan(
rateBound,
"the one-shot retry must absorb the overwhelming majority of raced clears; " +
$"{exhausted}/{totalEvaluations} evaluations exhausted it");
$"{exhausted}/{totalEvaluations} evaluations exhausted it" + Diagnostics());
// (3) The starvation bucket is tolerated but not unbounded — at 10% the evaluator has stopped
// evaluating rather than the box being busy.
starved.ShouldBeLessThan(
rateBound,
"queue-starvation timeouts are expected under this stress but must stay marginal; " +
$"{starved}/{totalEvaluations} evaluations missed the 5s budget");
$"{starved}/{totalEvaluations} evaluations missed the 5s budget" + Diagnostics());
}
// ── input quality reaches the script (archreview 02/S14) ────────────────────────────────
@@ -125,9 +125,14 @@ public sealed class SupervisionTests
/// A burst of cold compiles must not starve the worker's heartbeat. Found on windev by the §8 perf harness: 500
/// loads at once, each compiled synchronously on its own thread-pool work item, queued the heartbeat timer and
/// the pipe writer behind them; the host saw no frame for 3 s, killed the shard (KilledHeartbeat) and made all 500
/// keys suspects. Here a 100 ms heartbeat (kill after 300 ms of silence) and 400 distinct cold scripts at once:
/// every script answers and the shard's worker is the one that started. Mutation check: compile on the thread
/// pool again and the worker is killed for silence.
/// keys suspects. Here a 50 ms heartbeat (kill after 3 s of silence, production's limit) and 1,500 distinct cold scripts at once:
/// every script answers and the shard's worker is the one that started.
/// <para>⚠️ The old "mutation check: compile on the thread pool again and the worker is killed for silence" does
/// NOT hold any more (re-checked for lmxopcua#843 on a 14-core Mac: the mutated worker passed at both the 150 ms
/// and the 1 s limit). The host's silence clock counts ANY frame, and since lmxopcua#789 a compile writes its own
/// <c>LoadStarted</c>/<c>LoadResult</c> frames inline — so pool-queued compiles keep the pipe busy themselves (the 3 s silence
/// windev saw presumably also needed the pre-#789 pool-scheduled writer stuck behind them). What this still pins is the
/// behaviour: a cold burst under a tight heartbeat is answered without a kill.</para>
/// </summary>
[Fact]
public async Task A_burst_of_cold_compiles_does_not_starve_the_heartbeat()
@@ -136,13 +141,29 @@ public sealed class SupervisionTests
var heartbeat = TimeSpan.FromMilliseconds(50);
await using var runner = TightHeartbeatRunner(heartbeat, TimeSpan.FromSeconds(120), sink);
var worker = WarmTight(runner, await runner.RunAsync(Scripts.Vt("first", Healthy), Ct), heartbeat, sink);
// lmxopcua#843: three 50 ms intervals (150 ms) is a limit the OS scheduler alone breaks on an overloaded box — at
// load average 100–280 the worker or the host's reader waited 150–310 ms for a core (10/10 runs killed for silence
// under 28 CPU burners, every compile on its dedicated thread), and at ~300 even a 1 s limit was hit once in 10
// (1,012 ms). The limit is now PRODUCTION's (3 × the default 1 s heartbeat): the test kills only where a real node
// would, and the windev defect (no frame for 3 s, the whole burst) is still the size it catches. The 50 ms
// heartbeat keeps frames flowing for the silence clock.
worker.SilenceLimit = TimeSpan.FromSeconds(3);
const int count = 1500;
var burst = Stopwatch.StartNew();
var outcomes = await Task.WhenAll(Enumerable.Range(0, count).Select(i => runner.RunAsync(
Scripts.Vt("burst-" + i, $"return (int)ctx.GetTag(\"x\").Value * {i} + 1;", TimeSpan.FromSeconds(60),
Scripts.Input("x", 2)), Ct)));
burst.Stop();
var log = string.Join(Environment.NewLine, sink.Rendered.Where(l => l.Contains("ScriptWorker", StringComparison.Ordinal)).Take(5));
// The kill line ("sent nothing for N ms") against the burst's length is the diagnosis: N close to the burst is
// the pool-starvation defect, N just over the limit is a starved box.
var log = $"burst took {burst.ElapsedMilliseconds} ms, silence limit {worker.SilenceLimit.TotalMilliseconds} ms\n"
+ string.Join(Environment.NewLine, sink.Rendered
.Where(l => l.Contains("ScriptWorker", StringComparison.Ordinal))
.Where(l => l.Contains("sent nothing", StringComparison.Ordinal) || l.Contains("kill", StringComparison.OrdinalIgnoreCase)
|| l.Contains("exit", StringComparison.OrdinalIgnoreCase))
.Take(10));
for (var i = 0; i < count; i++) outcomes[i].Value.ShouldBe(2 * i + 1, $"{outcomes[i].Status} {outcomes[i].Reason}\n{log}");
runner.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid, log);
worker.Exited.IsCompleted.ShouldBeFalse(log);