Flaky under load: Galaxy EventPumpBoundedChannelTests.Drops_newest_when_channel_fills_and_records_metric #503

New Issue

2026-07-25T22:44:54-04:00

dohertj2 commented

2026-07-25 22:44:54 -04:00

Found while running the full unit-test sweep on merged master (28c28667). Pre-existing and unrelated to that merge — EventPumpBoundedChannelTests.cs is untouched by it, and the file's last change (560b327e) predates the work.

Test: ZB.MOM.WW.OtOpcUa.Driver.Galaxy.Tests.Runtime.EventPumpBoundedChannelTests.Drops_newest_when_channel_fills_and_records_metric

Failure: Shouldly.ShouldAssertException : counters.Received — the drop metric did not reach the expected count.

Reproduction (measured):

25 consecutive runs of Driver.Galaxy.Tests in isolation -> 0 failures.
12 runs with Runtime.Tests + AdminUI.Tests + Core.Tests running concurrently -> 1 failure (run 11).
Also failed once during a full 41-project sweep.

So it needs CPU contention, like the #500 family did. Recipe that catches it:

for i in $(seq 1 12); do
  dotnet test tests/Server/…Runtime.Tests --no-build > /dev/null 2>&1 &
  dotnet test tests/Server/…AdminUI.Tests --no-build > /dev/null 2>&1 &
  dotnet test tests/Core/…Core.Tests     --no-build > /dev/null 2>&1 &
  dotnet test tests/Drivers/…Galaxy.Tests --no-build \
    --logger "trx;LogFileName=/tmp/gal/run$i.trx" 2>&1 | grep -E "Failed!|Passed!"
  wait
done

Always capture trx — a summary-only run loses the test name and costs a full re-run to recover.

Likely shape (not yet confirmed — I did not diagnose this one). The test drives a bounded channel to overflow and asserts a drop count. Counts like that are usually observed after a producer/consumer race, so the assertion can be evaluated before the drops have been recorded, or the consumer can drain fast enough under different scheduling that fewer drops occur than the test assumes. Worth checking which of those it is before changing anything — #500 had two hypotheses that looked obvious and were both wrong under measurement.

See #500 for the presence-vs-absence assertion rule, which resolved eight tests of a similar character in Runtime.Tests.

Found while running the full unit-test sweep on merged master (`28c28667`). **Pre-existing and unrelated to that merge** — `EventPumpBoundedChannelTests.cs` is untouched by it, and the file's last change (`560b327e`) predates the work. **Test:** `ZB.MOM.WW.OtOpcUa.Driver.Galaxy.Tests.Runtime.EventPumpBoundedChannelTests.Drops_newest_when_channel_fills_and_records_metric` **Failure:** `Shouldly.ShouldAssertException : counters.Received` — the drop metric did not reach the expected count. **Reproduction (measured):** - 25 consecutive runs of `Driver.Galaxy.Tests` **in isolation** -> 0 failures. - 12 runs **with `Runtime.Tests` + `AdminUI.Tests` + `Core.Tests` running concurrently** -> **1 failure** (run 11). - Also failed once during a full 41-project sweep. So it needs CPU contention, like the #500 family did. Recipe that catches it: ```bash for i in $(seq 1 12); do dotnet test tests/Server/…Runtime.Tests --no-build > /dev/null 2>&1 & dotnet test tests/Server/…AdminUI.Tests --no-build > /dev/null 2>&1 & dotnet test tests/Core/…Core.Tests --no-build > /dev/null 2>&1 & dotnet test tests/Drivers/…Galaxy.Tests --no-build \ --logger "trx;LogFileName=/tmp/gal/run$i.trx" 2>&1 | grep -E "Failed!|Passed!" wait done ``` Always capture `trx` — a summary-only run loses the test name and costs a full re-run to recover. **Likely shape (not yet confirmed — I did not diagnose this one).** The test drives a bounded channel to overflow and asserts a *drop* count. Counts like that are usually observed after a producer/consumer race, so the assertion can be evaluated before the drops have been recorded, or the consumer can drain fast enough under different scheduling that fewer drops occur than the test assumes. Worth checking which of those it is before changing anything — #500 had two hypotheses that looked obvious and were both wrong under measurement. See #500 for the presence-vs-absence assertion rule, which resolved eight tests of a similar character in `Runtime.Tests`.

dohertj2 commented

2026-07-26 10:43:01 -04:00

Fixed on fix/issues-503-501-493-499-488, commit 95295210.

The "likely shape" in the issue was wrong, and so was my own first fix. It is not a producer/consumer timing race. It is cross-test measurement leakage.

EventPump's Meter is static (one per process — the correct production shape, so a host-level listener catches every pump), and MeterListener.InstrumentPublished can only select by meter. StartMeterCapture therefore collected measurements from every EventPump alive anywhere in the assembly. xUnit runs test classes in parallel and several build pumps — EventPumpStreamFaultTests, and the Driver-X test in this same file. A sibling's events landed in these counters. That is exactly why it needed a busy box: it needed two tests to overlap in time. Measured directly during the gate: Received = 11 in a run that emitted 10.

The third test in the file already filtered on the galaxy.client tag and even documents why. The broken one did not. Fixed by filtering the capture on a per-test unique tag (PumpTest-{guid}), not a literal.

Why the failure surfaced as counters.Received. The Received == Dispatched + Dropped + InFlight assertion could only ever fail spuriously: InFlight was derived as Received - Dispatched - Dropped, making the identity a tautology. A foreign increment landing between its four separate Interlocked.Read calls is the only way to break it. Deleted, along with the InFlight member; the three measured counters are asserted directly.

Three more defects in the same test, all found on the way:

The "held" dispatch loop was never held. OnDataChange is EventHandler<T> — void-returning — so async (_, _) => await gate is async void: it returns to the loop at the first await and blocks nothing. Measured Dispatched = 2..3, never 0. Drops occurred only when the producer happened to outrun the consumer, so the arrangement the doc comment describes was fiction. Now a synchronous ManualResetEventSlim.Wait() on the loop's own thread, pinned by Dispatched.ShouldBe(0).
The fixed Task.Delay(150) is now a presence poll on the drop count (#500's rule); Dropped starts at 0 so it cannot be satisfied by the initial state.
Emission is staged — one event, wait for the dispatcher to enter the handler, then the other nine — so the arithmetic is exact (10 - 1 held - 2 buffered = 7) rather than scheduler-dependent.

Gate release moved into finally, ahead of disposal: DisposeAsync awaits the dispatch loop, which is now genuinely parked, so a failed assertion would otherwise hang rather than fail.

Verification: 15/15 clean under the exact recipe in this issue (full Galaxy project with Runtime + AdminUI + Core concurrent). Worth noting the intermediate state — with only the async-void/timing half fixed, the gate still failed on run 4, which is what exposed the leak. Falsifiability: restoring the async-void handler turns the new assertions red.

Test duration also dropped from ~220 ms to ~45 ms (no fixed sleep).

Fixed on `fix/issues-503-501-493-499-488`, commit `95295210`. **The "likely shape" in the issue was wrong, and so was my own first fix.** It is not a producer/consumer timing race. It is **cross-test measurement leakage**. `EventPump`'s `Meter` is **static** (one per process — the correct production shape, so a host-level listener catches every pump), and `MeterListener.InstrumentPublished` can only select by *meter*. `StartMeterCapture` therefore collected measurements from **every `EventPump` alive anywhere in the assembly**. xUnit runs test classes in parallel and several build pumps — `EventPumpStreamFaultTests`, and the `Driver-X` test in this same file. A sibling's events landed in these counters. That is exactly why it needed a busy box: it needed two tests to *overlap in time*. Measured directly during the gate: **`Received = 11` in a run that emitted 10.** The third test in the file already filtered on the `galaxy.client` tag and even documents why. The broken one did not. Fixed by filtering the capture on a per-test **unique** tag (`PumpTest-{guid}`), not a literal. **Why the failure surfaced as `counters.Received`.** The `Received == Dispatched + Dropped + InFlight` assertion could only ever fail spuriously: `InFlight` was **derived** as `Received - Dispatched - Dropped`, making the identity a tautology. A foreign increment landing between its four separate `Interlocked.Read` calls is the only way to break it. Deleted, along with the `InFlight` member; the three *measured* counters are asserted directly. **Three more defects in the same test, all found on the way:** - **The "held" dispatch loop was never held.** `OnDataChange` is `EventHandler<T>` — void-returning — so `async (_, _) => await gate` is **async void**: it returns to the loop at the first `await` and blocks nothing. Measured `Dispatched = 2..3`, never 0. Drops occurred only when the producer happened to outrun the consumer, so the arrangement the doc comment describes was fiction. Now a synchronous `ManualResetEventSlim.Wait()` on the loop's own thread, pinned by `Dispatched.ShouldBe(0)`. - **The fixed `Task.Delay(150)`** is now a presence poll on the drop count (#500's rule); `Dropped` starts at 0 so it cannot be satisfied by the initial state. - **Emission is staged** — one event, wait for the dispatcher to enter the handler, then the other nine — so the arithmetic is exact (`10 - 1 held - 2 buffered = 7`) rather than scheduler-dependent. Gate release moved into `finally`, ahead of disposal: `DisposeAsync` awaits the dispatch loop, which is now genuinely parked, so a failed assertion would otherwise **hang** rather than fail. **Verification: 15/15 clean** under the exact recipe in this issue (full Galaxy project with Runtime + AdminUI + Core concurrent). Worth noting the intermediate state — with only the async-void/timing half fixed, the gate **still failed on run 4**, which is what exposed the leak. Falsifiability: restoring the async-void handler turns the new assertions red. Test duration also dropped from ~220 ms to ~45 ms (no fixed sleep).

dohertj2 closed this issue

2026-07-26 10:43:01 -04:00

dohertj2 referenced this issue from a commit

2026-07-26 10:53:53 -04:00

fix(test): scope the EventPump counter capture to its own pump (#503)

dohertj2 referenced this issue from a commit

2026-07-26 10:53:53 -04:00

merge: test-correctness, config-secret and AdminUI fixes (#503 #501 #493 #499 #488 #505)

dohertj2 referenced this issue

2026-07-26 11:45:55 -04:00

feat(raw): hot-rebind a renamed raw tag's live value without a node recreate #489

Sign in to join this conversation.