An Orleans failure can be read: the window is traced, silo faults are recorded, and a crashed host is a failed result (#2495) by rbuergi · Pull Request #2505 · Systemorph/MeshWeaver

rbuergi · 2026-08-27T14:08:48Z

Closes #2495.

What the measurement actually said

Taken from CI run 33062668925, shard 3, where MeshWeaver.Hosting.Orleans.Test ran 208 tests over 272 s and failed on OrleansAutoExecuteTest.AutoExecute_UpdateThreadMessageContent_RoutesToResponseGrain.

The StdOut reading was a false lead, and the contrast settles it. The shards run the NATIVE xUnit v3 host (dotnet <Name>.dll -trx …), whose trx writer puts captured output in <Output><TextMessages><Message> — <StdOut> is used only when a test writes to the process console. Across that whole run: Orleans 0/208 StdOut, PluginCatalog 0/640, Graph 0/1657 — and Portal.E2E 192/194, PluginImage 4/4, because those two shell out. Nothing needs fixing to make StdOut appear.

But the substance of the issue is right, and worse. The failing test's captured output is 167 lines, of which 165 predate === TEST START === — Orleans silo boot. The 13.8-second failure window holds two lines, both Orleans GC-watchdog warnings. Zero MeshWeaver lines.

And the trace genuinely did not cover the window. The per-test phase trace was written only by MonolithMeshTestBase. Lines in _meshweaver-test-trace.log by pid, same shard, same file:

host	lines
`MeshWeaver.Hosting.Orleans.Test` (208 tests, 272 s)	4
its three Monolith-derived shard-mates	819 / 606 / 1789

Those four are all [FAULT] records. OrleansSharedTestBase extends TestBase directly, so it wrote no phase lines at all.

What changed

1. Every project writes its test window. The markers move to AutoTestLoggingAttribute, which every TestBase subclass in every project already carries: TEST_START <method> / TEST_END elapsed=<n>ms <method> outcome=<…> :: <type>: <message>, with pid so a shard's several hosts stay apart. A TEST_START with no matching TEST_END names the test a killed host wedged in — the only evidence that survives exit=124, which writes no trx at all.

elapsed is measured between the hooks, not read off TestResultState.ExecutionTime: xUnit v3.2.2 documents that as seconds and it reports milliseconds (1523.705 for a test the trx records at 00:00:01.5306690), so trusting the doc would put every line out by 1000×.

2. Silo-side faults reach the file. The two xUnit loggers split the process by service provider, not by importance: XUnitFileLogger serves the TestBase container and wrote fault records; XUnitLogger serves everything built by a HOST — in an Orleans test the silo, the client, and every mesh hub and grain inside them — and wrote none. It now records a Warning-or-worse record carrying an exception to the same file, before the output-helper guard, exactly as XUnitFileLogger already did.

Same suite, same 208 green tests, locally at DOTNET_PROCESSOR_COUNT=4: 4 → 129 fault records, including categories that were entirely invisible — MeshWeaver.AI.ThreadExecution (13), Data.Serialization.SynchronizationStream (8), Hosting.MeshNodeStreamCache (3), Graph.Configuration.MeshNodeCompilationService (4), Orleans.Runtime.Messaging.Connection (65). FaultRecordBudget did not suppress once, so the healthy rate is inside budget.

3. 🚨 A crashed host is a FAILED result, not a silence. Pass/fail evidence (the trx) and liveness evidence (the exit marker) were two channels, and every reporter reads only the first — which is why MeshWeaver.Content.Test's exit=139 had the shard summary, the per-shard check and the consolidated check all announce a pass over three tests while the process had died. Adding a seventh checker would leave the next reporter with the same blind spot, so the evidence is single-channel now: for any exit the trx cannot explain, .github/scripts/record-host-crash.py writes a <project>.HOST_CRASHED failure into the trx, creating the file when the host wrote none.

Proof it fails loudly — every claim has a negative control

control	result
real host killed mid-run (`SIGKILL`, no trx written) → classify + record	shard gate goes RED, naming `MeshWeaver.Threading.Test.HOST_CRASHED`
real 366-passed trx + `rc=139` (the Content.Test shape)	counters `366/0` → `366 passed / 1 failed`, `ResultSummary` → `Failed`, gate RED
recorder replaced by a no-op	3 of 4 guard tests fail, naming the defect
`crash=` dropped from the SIGSEGV branch	classifier guard fails, naming exit code `139`
fault sink removed from `XUnitLogger`	`AFaultLoggedWithNoActiveTest_StillReachesTheOneLogCiKeeps` fails
window markers removed	`TheTestWindow_IsWrittenToTheOneLogCiKeeps` fails

CrashedHostIsNeverAPassGuard executes the real script (it does not pattern-match the workflow) against both shapes a dead host leaves behind, and asserts with the shard gate's own grep. Its wiring half fails if any death branch stops setting crash=, so a new exit code cannot be given a marker without also being given a trx result.

🚨 The window pin's first version passed with the mechanism deleted — it read a shared, append-only file whole and found a previous green run's line. In a change whose entire subject is verification steps that cannot fail, that is the one mistake not to ship: it is now anchored to a length captured in the constructor and matches on pid.

What it already tells you about an unattributed #2346 member

AutoExecute_UpdateThreadMessageContent_RoutesToResponseGrain is still listed as unfixed and unattributed. Joining the window brackets to the trx times says what no artifact previously did:

it failed with six other test classes executing in the same process — OrleansChatHistoryTest, OrleansHostedHubRoutingTest, OrleansReentrancyTest, OrleansStaticRepoImportTest, OrleansThreadStreamingTest, SiloShutdownActivationGateTest — and OrleansSharedTestBase boots one Orleans cluster per class;
the one [FAULT] [Critical] record inside its window (portal/silo-shutdown-sender, "cross-process routing DISABLED", 10:31:30.292) belongs to SiloShutdownActivationGateTest.ShutdownFlippingAfterTheGate_IsRefusedAsTransient_NotTerminal (10:31:28.893 → 10:31:30.309) — a concurrent class deliberately shutting a silo down, four seconds before the assertion failed;
the two watchdog lines in the window are the same event from the runtime's side: "stalled for 00:00:02.17, GC Pause 00:00:01.59", and a timer 4.86 s late.

Detail and caveats in the issue comment. Locally the suite is 208/208 green, so this is a lead with named candidates, not a root cause.

Known gap, stated rather than implied

The window markers come from an attribute on TestBase, so a class that does not derive from it writes none — 25 classes / 86 of 208 tests in Orleans.Test (RoutingGrain*, OrleansCrossSilo*, TwoSiloRecycleConvergenceTest, …). Their faults still reach the file; only the brackets are missing. Closing it needs an assembly-level attribute in an assembly every test project references, which today is neither MeshWeaver.Fixture (21 of 45 projects do not reference it) nor MeshWeaver.Reactive.Assertions (a published package whose contract is "depends only on System.Reactive"). Left as follow-up rather than smuggled in.

Verification

Release + -warnaserror throughout. Orleans.Test 208/208 at DOTNET_PROCESSOR_COUNT=4 (twice, 67 s and 90 s), Query.Test 409/409, Documentation.Test 91/91.

🤖 Generated with Claude Code

… recorded, and a crashed host is a failed result (#2495) Three separate defects, measured on CI run 33062668925 (shard 3), where MeshWeaver.Hosting.Orleans.Test ran 208 tests over 272 seconds. 1. The trx was never empty — it was 99% pre-test noise. The shards run the NATIVE xUnit v3 host, whose trx writer puts captured output in <Output><TextMessages>, NOT <StdOut> (only Portal.E2E and PluginImage populate StdOut, because they write to the process console). So "223 results with an empty StdOut" is true of every project and says nothing about any of them. What IS true: the failing Orleans test carried 167 lines of which 165 predate `=== TEST START ===` — silo boot — leaving TWO lines in the 13.8 s failure window, both Orleans GC-watchdog warnings. 2. The one log CI keeps had no coverage of that window. The per-test phase trace was written only by MonolithMeshTestBase, so the Orleans host contributed FOUR lines to _meshweaver-test-trace.log against 819 / 606 / 1789 from its three shard-mates. The markers now come from AutoTestLoggingAttribute, which every TestBase subclass in every project already carries: TEST_START / TEST_END elapsed=<n>ms outcome=<…> with the exception type and message, carrying pid so a shard's four hosts stay apart. A TEST_START with no TEST_END names the test a killed host wedged in — the only evidence that survives exit=124, which writes no trx at all. elapsed is MEASURED, not read off TestResultState.ExecutionTime: xUnit v3.2.2 documents that as seconds and it reports milliseconds (1523.705 for a test the trx records at 00:00:01.5306690), so trusting the doc puts every line out by 1000x. 3. Silo-side faults reached no artifact at all. The two xUnit loggers split the process by SERVICE PROVIDER, not by importance: XUnitFileLogger serves the TestBase container and wrote fault records; XUnitLogger serves everything built by a HOST — in an Orleans test the silo, the client, and every hub and grain inside them — and wrote none. XUnitLogger now records a Warning-or-worse record carrying an exception to the same file, BEFORE the output-helper guard, exactly as XUnitFileLogger does. Same suite, same 208 green tests: 4 fault records -> 129, including categories that were entirely invisible (AI.ThreadExecution, SynchronizationStream, MeshNodeStreamCache, MeshNodeCompilationService, Orleans.Messaging.Connection). FaultRecordBudget did not suppress once, so the healthy rate is inside budget. 4. A crashed host could be summarised as a pass. Pass/fail evidence (the trx) and liveness evidence (the exit marker) were two channels, and every reporter reads only the first — so MeshWeaver.Content.Test's exit=139 had the shard summary, the per-shard check and the consolidated check all announce "3 passed" over a dead process. Adding a seventh checker would leave the next reporter with the same blind spot, so the evidence is single-channel now: for any exit the trx cannot explain, .github/scripts/record-host-crash.py writes a <project>.HOST_CRASHED failure INTO the trx, creating the file when the host wrote none. A pass over a crash is no longer stateable by anything that parses it. Proven, not asserted. CrashedHostIsNeverAPassGuard runs the real script against both shapes a dead host leaves behind and asserts with the shard gate's own grep; the classifier half fails if any death branch stops setting `crash=`. Both new sink pins live beside the existing ones in TestOutputLoggingLifecycleTest. Every one was checked against its own negative control: neutering the recorder reds 3 of 4 guard tests, dropping crash= from the SIGSEGV branch reds the fourth, and removing either sink reds its pin. The window pin's first version PASSED with the mechanism deleted — it read a shared append-only file whole and found a previous run's line — so it is anchored to a length captured in the constructor and matches on pid. Local verification: Orleans.Test 208/208 green at DOTNET_PROCESSOR_COUNT=4 (twice), Query.Test 409/409, Documentation.Test 91/91, all Release + -warnaserror. Known gap, documented rather than implied: the window markers come from an attribute on TestBase, so classes that do not derive from it write none — 25 classes / 86 of 208 tests in Orleans.Test. Their faults still reach the file; only the brackets are missing. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Copilot

Pull request overview

This PR improves CI diagnosability and correctness for test-host failures, especially for Orleans-hosted flakes, by ensuring (1) every test’s execution window is traceable in the shard trace, (2) silo-side exceptions reach the one CI-kept log, and (3) a crashed/killed test host is represented as a failed TRX result (so no TRX-based reporter can summarize it as “passed”).

Changes:

Add per-test TEST_START/TEST_END window markers to the shard trace via AutoTestLoggingAttribute, with measured elapsed time and failure detail clamping.
Ensure XUnitLogger writes exception-bearing warning+ records into TestTraceLog even when no output helper is active.
Add a CI-side crash recorder (record-host-crash.py) and wire it into dotnet-test.yml so host deaths/masked exits/missing-bin/no-classes produce a <project>.HOST_CRASHED failed TRX result; add guard tests and documentation updates.

Reviewed changes

Copilot reviewed 11 out of 11 changed files in this pull request and generated 1 comment.

Show a summary per file

File	Description
test/MeshWeaver.Query.Test/TestOutputLoggingLifecycleTest.cs	Adds pins for window markers and fault sink reaching `_meshweaver-test-trace.log`.
test/MeshWeaver.Documentation.Test/CrashedHostIsNeverAPassGuard.cs	New negative-control tests that execute the real crash-recorder script and validate workflow wiring.
src/MeshWeaver.Hosting.Monolith.TestBase/MonolithMeshTestBase.cs	Routes phase trace formatting through `TestTraceLog.AppendPhase` to keep formats consistent.
src/MeshWeaver.Fixture/TestTraceLog.cs	Introduces `AppendPhase(...)` canonical formatter used by multiple writers.
src/MeshWeaver.Fixture/LoggingBuilderExtensions.cs	Writes exception-bearing warning+ logs to `TestTraceLog` before output-helper gating (fixes Orleans silo invisibility).
src/MeshWeaver.Fixture/AutoTestLoggingAttribute.cs	Writes `TEST_START`/`TEST_END` window markers + measured elapsed and failure details into `TestTraceLog`.
src/MeshWeaver.Documentation/Data/Architecture/WritingTests.md	Documents how to read CI artifacts, including window markers and crash-as-failed-TRX behavior.
src/MeshWeaver.Documentation/Data/Architecture/AsyncLocalAcrossHops.md	Notes that fault records now survive missing output-helper AsyncLocal in relevant cases.
AGENTS.md	Adds concise “read the evidence” guidance + pointers to the new documentation section.
.github/workflows/dotnet-test.yml	Wires crash recording into the shard runner and clarifies summaries; adds recording for missing-bin/no-classes.
.github/scripts/record-host-crash.py	New script that injects a `<project>.HOST_CRASHED` failed result into (or creates) a TRX.

Suppressed comments (1)

.github/workflows/dotnet-test.yml:1034

The NO_CLASSES branch also runs record-host-crash.py without checking for failure. If the recorder fails here, the split-project part still produces no trx and becomes invisible to trx-based summarizers. Add the same guarded invocation + CRASH_RECORD_FAILED marker used later in the main crash-recording block.

            if [ "${#allclasses[@]}" -eq 0 ]; then
              echo "::error::$label: could not enumerate test classes — refusing to run a partial shard silently."
              echo "[CI] $name exit=96 NO_CLASSES (class enumeration failed for a split project)" >> test/test-results.log
              python3 .github/scripts/record-host-crash.py \
                "$dir/TestResults/$name.part$part.trx" "$label" 96 \
                "NO_CLASSES: class enumeration failed for a split project, so this part ran nothing."

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

…e logger's fast path Two fixes from the Copilot review + a measurement. 1. The MISSING_BIN and NO_CLASSES call sites invoked record-host-crash.py without checking its exit code, directly under a comment promising the project would not stay invisible to trx readers — prose asserting a guarantee the code did not provide. Both now use the same `if ! …; then ::error:: + CRASH_RECORD_FAILED; fi` shape as the classifier's call. CrashedHostIsNeverAPassGuard no longer looks for ONE guarded invocation: it enumerates every `record-host-crash.py` call in the workflow and requires each to be guarded and to emit both signals. Verified by negative control — unguarding the MISSING_BIN call reds the guard with "a recorder call whose exit code is discarded is the same silence with an extra step". 2. XUnitLogger keeps its original fast path for the common record. Only a Warning-or-worse record carrying an exception can reach the fault sink; everything else exits on the same single null check it always did, instead of first walking the filter rules. That matters because this logger is on the hot path of an Orleans silo logging at Information, where the output helper is null on every grain-scheduler thread. Measured on a quiet machine: Orleans.Test 67.1 s without the sink, 72.2 s with IsEnabled hoisted (72.167 / 72.264, reproducible). The comment says plainly that the sink's own ~125 records are inside that delta too, so the hoist is not credited with all 5 s — only with buying nothing. Orleans.Test 208/208, Query.Test 4/4 sink pins, Documentation.Test guard 4/4, all Release + -warnaserror. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

github-actions · 2026-08-27T14:38:19Z

Test Results (shard 2)

1 006 tests 814 ✅ 5m 30s ⏱️
7 suites 192 💤
7 files 0 ❌

Results for commit 1ff40a5.

github-actions · 2026-08-27T14:38:25Z

Test Results (shard 4)

7 files 7 suites 10m 55s ⏱️
4 407 tests 4 404 ✅ 3 💤 0 ❌
5 002 runs 4 999 ✅ 3 💤 0 ❌

Results for commit 1ff40a5.

github-actions · 2026-08-27T14:38:46Z

Test Results (shard 5)

1 583 tests 1 582 ✅ 9m 38s ⏱️
9 suites 1 💤
9 files 0 ❌

Results for commit 1ff40a5.

github-actions · 2026-08-27T14:38:51Z

Test Results (shard 3)

1 083 tests 1 083 ✅ 17m 28s ⏱️
8 suites 0 💤
8 files 0 ❌

Results for commit 1ff40a5.

github-actions · 2026-08-27T14:39:18Z

Test Results (shard 0)

1 379 tests 1 379 ✅ 6m 8s ⏱️
6 suites 0 💤
6 files 0 ❌

Results for commit 1ff40a5.

github-actions · 2026-08-27T14:39:27Z

Test Results (shard 1)

845 tests 841 ✅ 7m 17s ⏱️
8 suites 4 💤
8 files 0 ❌

Results for commit 1ff40a5.

github-actions · 2026-08-27T14:39:53Z

Test Results

45 files 45 suites 56m 58s ⏱️
10 301 tests 10 101 ✅ 200 💤 0 ❌
10 898 runs 10 698 ✅ 200 💤 0 ❌

Results for commit 1ff40a5.

Copilot AI lite review requested due to automatic review settings August 27, 2026 14:08

Copilot started reviewing on behalf of rbuergi August 27, 2026 14:09

View session

Copilot AI reviewed Aug 27, 2026

View reviewed changes

Comment thread .github/workflows/dotnet-test.yml Outdated

rbuergi mentioned this pull request Aug 27, 2026

Orleans.Test failures cannot be read: all 223 results carry an empty StdOut in CI — the flake cluster is attributed by inference for want of it #2495

Closed

rbuergi merged commit 7126b08 into main Aug 27, 2026
23 checks passed

rbuergi deleted the fix/2495-orleans-test-diagnostics branch August 28, 2026 08:56

Navigation Menu

Repository navigation

An Orleans failure can be read: the window is traced, silo faults are recorded, and a crashed host is a failed result (#2495) - #2505

An Orleans failure can be read: the window is traced, silo faults are recorded, and a crashed host is a failed result (#2495)#2505
rbuergi merged 2 commits into
mainfrom
fix/2495-orleans-test-diagnostics

rbuergi commented Aug 27, 2026

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

github-actions Bot commented Aug 27, 2026

Uh oh!

github-actions Bot commented Aug 27, 2026

Uh oh!

github-actions Bot commented Aug 27, 2026

Uh oh!

github-actions Bot commented Aug 27, 2026

Uh oh!

github-actions Bot commented Aug 27, 2026

Uh oh!

github-actions Bot commented Aug 27, 2026

Uh oh!

github-actions Bot commented Aug 27, 2026

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Conversation

rbuergi commented Aug 27, 2026

What the measurement actually said

What changed

Proof it fails loudly — every claim has a negative control

What it already tells you about an unattributed #2346 member

Known gap, stated rather than implied

Verification

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Reviewed changes

Uh oh!

Uh oh!

github-actions Bot commented Aug 27, 2026

Test Results (shard 2)

Uh oh!

github-actions Bot commented Aug 27, 2026

Test Results (shard 4)

Uh oh!

github-actions Bot commented Aug 27, 2026

Test Results (shard 5)

Uh oh!

github-actions Bot commented Aug 27, 2026

Test Results (shard 3)

Uh oh!

github-actions Bot commented Aug 27, 2026

Test Results (shard 0)

Uh oh!

github-actions Bot commented Aug 27, 2026

Test Results (shard 1)

Uh oh!

github-actions Bot commented Aug 27, 2026

Test Results

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants