Intermittent single-test failure in Runtime.Tests under full-sweep load (unidentified) #500

Open
opened 2026-07-25 16:08:59 -04:00 by dohertj2 · 1 comment
Owner

Observed while verifying the #496/#497/#498 branch, filed so it is not lost.

Symptom: running every unit-test project back to back, ZB.MOM.WW.OtOpcUa.Runtime.Tests reported Failed: 1, Passed: 497 (of 529). It has done this twice, on two separate full sweeps.

What I could not do: identify the test. My sweep loop only captured the summary line, and the failure has not reproduced since.

Not reproducible in:

  • 7 consecutive isolated runs with the branch changes — all 498 passed
  • 4 consecutive isolated runs at baseline (changes stashed) — all 498 passed
  • 2 rounds with AdminUI.Tests + OpcUaServer.Tests + Core.Tests running concurrently to imitate sweep load — both green

So it appears only under whole-sweep timing pressure, which fits Runtime.Tests being Akka-actor-heavy and timing-sensitive.

Believed unrelated to the branch: the only file in Runtime.Tests referencing any symbol that branch touched is DriverInstanceActorTests, and the change there was a one-word comment correction (a test-local constant 0x80340000 was labelled BadOutOfService; it is BadNodeIdUnknown, and only its severity bits are load-bearing). Baseline shows the same non-reproducibility, though baseline never actually reproduced the failure either, so that is weak evidence.

To pin it down: re-run the full sweep capturing per-test output, e.g. dotnet test <proj> --logger \"trx\" for every project, and inspect the .trx on failure.

Observed while verifying the #496/#497/#498 branch, filed so it is not lost. **Symptom:** running every unit-test project back to back, `ZB.MOM.WW.OtOpcUa.Runtime.Tests` reported `Failed: 1, Passed: 497` (of 529). It has done this **twice**, on two separate full sweeps. **What I could not do:** identify the test. My sweep loop only captured the summary line, and the failure has not reproduced since. **Not reproducible in:** - 7 consecutive isolated runs with the branch changes — all `498 passed` - 4 consecutive isolated runs at baseline (changes stashed) — all `498 passed` - 2 rounds with AdminUI.Tests + OpcUaServer.Tests + Core.Tests running concurrently to imitate sweep load — both green So it appears only under whole-sweep timing pressure, which fits `Runtime.Tests` being Akka-actor-heavy and timing-sensitive. **Believed unrelated to the branch:** the only file in `Runtime.Tests` referencing any symbol that branch touched is `DriverInstanceActorTests`, and the change there was a one-word comment correction (a test-local constant `0x80340000` was labelled `BadOutOfService`; it is `BadNodeIdUnknown`, and only its severity bits are load-bearing). Baseline shows the same non-reproducibility, though baseline never actually reproduced the failure either, so that is weak evidence. **To pin it down:** re-run the full sweep capturing per-test output, e.g. `dotnet test <proj> --logger \"trx\"` for every project, and inspect the `.trx` on failure.
Author
Owner

Fixed on fix/sql-driver-followups (154171f4). Verification: 30 consecutive full-assembly runs, 30 passed / 0 failed, against a measured 13% baseline.

Identification

Instrumented 30 runs with per-test trx capture: reproduced 4 times, five failures across three distinct tests. It was never one flaky test. My original note here said it "only appears under whole-sweep load" and "never in isolation" — that was wrong, just too small a sample (15 runs).

Two hypotheses disproved by measurement before changing anything

  • Cluster-formation timeout. Every test forms a real single-node Akka cluster over TCP in RuntimeActorTestBase's constructor and waits 5 s for MemberStatus.Up — 219 formations per run, 44 classes running ~14-way parallel. Instrumented the wait: idle max 960 ms, under-load max 1470 ms, zero timeouts. A 3.4x margin — not the cause.
  • Ephemeral-port exhaustion from that bind churn. TIME_WAIT measured at ~0 throughout — not the cause.

Four genuine ordering/logic defects (none a timeout)

  1. ApplyVirtualTags_respawns_child_when_plan_changes_in_place — the test loops to accept RegisterInterest/UnregisterInterest in either order, then asserts on mux.LastSender, which depends on that order. Under [Register, Unregister], LastSender is the dying child. Now captures the sender of the Register message as it arrives — deterministic. (Swept the other four LastSender sites: all drain the Unregister first, so only this one was unsafe.)
  2. Primary_routes_write_via_uns_nodeid_to_driver_by_rawpathApplyAck marks the end of the apply, not the point a write can succeed; the child is still in Connecting, which deliberately fast-fails writes. Retries until accepted. Does not weaken the assertion: every rejection branch replies without reaching the driver, so Writes.Count.ShouldBe(1) still means what it did.
  3. Redundancy_snapshot_without_local_node_... — one 500 ms constant served both presence budgets and absence windows, so the former could not be raised without slowing the latter. Split.
  4. Retry_after_writer_failure_eventually_acks — waited on outbox == 0, which is also true before the first append, so the poll could return having observed the initial state. Both conditions now polled together. (The preceding test in the same file documents this exact trap.)

The presence-budget class

After those four, three consecutive 30-run rounds each still failed once — on a different test in a different file every time (2 s, 2 s, 500 ms). That is a distribution, not a defect; fixing it one test at a time was the wrong method.

RuntimeActorTestBase now carries a documented PresenceBudget (15 s), with 57 sub-3 s AwaitAssert/AwaitCondition durations across four files routed through it.

Why that is safe and not just "make the timeout bigger": a presence budget is an upper bound before giving up, not a wait — the helper polls and returns the instant the condition holds. Raising it costs nothing on the happy path and cannot make a genuinely failing assertion pass; it only changes how quickly a real breakage reports. Absence windows are the opposite (elapsed time is the assertion) and were left untouched with their own short literals.

ScriptedAlarmHostActorTests was diagnosed rather than merely raised: its 8 s budget was sized for message passing but actually waits on a real Roslyn compile (ApplyScriptedAlarms -> ScriptedAlarmEngine.LoadAsync compiles every predicate). Cold script compiles are the slowest, most variable thing in the assembly, so that class gets 30 s with the reason recorded.

Related

  • #501 — two alarm-ack tests use AwaitAssert for an absence assertion, so they return instantly and prove nothing. Deliberately excluded from the budget change: a bigger number does not fix them, and the rewrite may legitimately turn them red.
  • #502 — filed mid-investigation when I had decided not to bulk-raise the remaining budgets. That decision was overturned by the evidence above and the work is now done here; #502 should be closed as superseded.
Fixed on `fix/sql-driver-followups` (`154171f4`). Verification: **30 consecutive full-assembly runs, 30 passed / 0 failed**, against a measured 13% baseline. ## Identification Instrumented 30 runs with per-test `trx` capture: reproduced 4 times, **five failures across three distinct tests**. It was never one flaky test. My original note here said it "only appears under whole-sweep load" and "never in isolation" — that was wrong, just too small a sample (15 runs). ## Two hypotheses disproved by measurement before changing anything - **Cluster-formation timeout.** Every test forms a real single-node Akka cluster over TCP in `RuntimeActorTestBase`'s constructor and waits 5 s for `MemberStatus.Up` — 219 formations per run, 44 classes running ~14-way parallel. Instrumented the wait: idle max **960 ms**, under-load max **1470 ms**, zero timeouts. A 3.4x margin — not the cause. - **Ephemeral-port exhaustion** from that bind churn. `TIME_WAIT` measured at ~0 throughout — not the cause. ## Four genuine ordering/logic defects (none a timeout) 1. **`ApplyVirtualTags_respawns_child_when_plan_changes_in_place`** — the test loops to accept `RegisterInterest`/`UnregisterInterest` in *either* order, then asserts on `mux.LastSender`, which **depends on that order**. Under `[Register, Unregister]`, `LastSender` is the *dying* child. Now captures the sender of the Register message as it arrives — deterministic. (Swept the other four `LastSender` sites: all drain the Unregister first, so only this one was unsafe.) 2. **`Primary_routes_write_via_uns_nodeid_to_driver_by_rawpath`** — `ApplyAck` marks the end of the *apply*, not the point a write can succeed; the child is still in `Connecting`, which deliberately fast-fails writes. Retries until accepted. Does not weaken the assertion: every rejection branch replies *without reaching the driver*, so `Writes.Count.ShouldBe(1)` still means what it did. 3. **`Redundancy_snapshot_without_local_node_...`** — one 500 ms constant served both presence budgets and absence windows, so the former could not be raised without slowing the latter. Split. 4. **`Retry_after_writer_failure_eventually_acks`** — waited on `outbox == 0`, which is **also true before the first append**, so the poll could return having observed the *initial* state. Both conditions now polled together. (The preceding test in the same file documents this exact trap.) ## The presence-budget class After those four, three consecutive 30-run rounds each still failed once — on a **different test in a different file every time** (2 s, 2 s, 500 ms). That is a distribution, not a defect; fixing it one test at a time was the wrong method. `RuntimeActorTestBase` now carries a documented `PresenceBudget` (15 s), with 57 sub-3 s `AwaitAssert`/`AwaitCondition` durations across four files routed through it. **Why that is safe and not just "make the timeout bigger":** a presence budget is an upper bound before giving up, not a wait — the helper polls and returns the instant the condition holds. Raising it costs nothing on the happy path and **cannot make a genuinely failing assertion pass**; it only changes how quickly a real breakage reports. Absence windows are the opposite (elapsed time *is* the assertion) and were left untouched with their own short literals. `ScriptedAlarmHostActorTests` was diagnosed rather than merely raised: its 8 s budget was sized for message passing but actually waits on a **real Roslyn compile** (`ApplyScriptedAlarms` -> `ScriptedAlarmEngine.LoadAsync` compiles every predicate). Cold script compiles are the slowest, most variable thing in the assembly, so that class gets 30 s with the reason recorded. ## Related - **#501** — two alarm-ack tests use `AwaitAssert` for an *absence* assertion, so they return instantly and prove nothing. Deliberately excluded from the budget change: a bigger number does not fix them, and the rewrite may legitimately turn them red. - **#502** — filed mid-investigation when I had decided *not* to bulk-raise the remaining budgets. That decision was overturned by the evidence above and the work is now done here; #502 should be closed as superseded.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: dohertj2/lmxopcua#500