/debug — Find where the message flow breaks down

A timeout means something never completed. The timeout is the symptom; the bug is a specific broken edge in the message flow — a message that was dropped, a handler that threw, an observer that died, an initial Full that was never sent, a Pending flip that never reached the owner. Raising the timeout never fixes this — it just hangs longer. Your job is to find the exact edge where the flow stops, and fix that.

Canonical reference: DebuggingMessageFlow.md (served at /Doc/Architecture/DebuggingMessageFlow). Read it — this skill is the operating procedure; the doc is the full trace-tag reference and the catalogue of known broken edges.

The one rule

Run once. Grep the trace. Find the last thing that fired and ask what should have fired next. Do not rerun "to see if it still sticks" (it will), and do not bump the timeout. A flake is a real race — pin the broken edge.

🚨 These hangs reproduce only IN BULK, not in isolation

The defining property of this class of bug: the test passes on its own and hangs only when the whole suite / project runs in one process. Run <TestName> alone → green; run the full project (or all four CI shards) → some test times out, and usually a different one each run. That is not "flakiness to retry away" — it is the tell that the broken edge is a cross-test interaction: shared scheduler/thread-pool pressure, a reused Orleans cluster, a per-process cache, an observer that only loses its race when other tests' emissions interleave, a grain that only deactivates→reactivates under concurrent load. A bug that vanishes in isolation is a bulk bug.

So reproduce in bulk, not in isolation:

# Reproduce the hang the way CI hits it — the whole project in ONE process:
dotnet test test/<Suite> --no-build > /tmp/trace.log 2>&1
# Narrow it: the class that ran JUST BEFORE the hung one is the prime suspect for the interaction.
grep -E "TEST CLASS INIT|TEST CLASS DISPOSE|\[FAIL\]|HandleMessageAsync ENTER" /tmp/trace.log | tail -60

The single-test run is only for confirming the fix once you've found the edge — never for deciding whether the bug exists. If the suite hangs but the test passes alone, the bug is real; keep digging in the bulk run.

Procedure

1. Crank logging to Trace in the test's runtime appsettings — NOT in src/ (log levels in source are a billed production contract; flipping them bleeds App Insights budget). Edit test/<Suite>/bin/Debug/net10.0/appsettings.json (reloadOnChange: true is wired); revert before committing:

   { "Logging": { "LogLevel": {
     "Default": "Information",
     "MeshWeaver.Messaging": "Trace",
     "MeshWeaver.Data.Serialization": "Trace",
     "MeshWeaver.Mesh": "Debug"
   } } }
   

2. Run the failing test exactly once, capturing everything:

   dotnet test test/<Suite> --no-build --filter "FullyQualifiedName~<TestName>" > /tmp/trace.log 2>&1
   

   Per-test logs also land at test/<Suite>/bin/Debug/net10.0/test-logs/<Class>_<Method>.log.

3. Grep the structured tags:

   grep -E "MESSAGE_FLOW|SYNC_STREAM|exception occurred|No handler found|DeliveryFailure|deliveryId" /tmp/trace.log
   

4. Find the LAST MESSAGE_FLOW: line that fired, then look at what should have happened next. This is the whole technique — the gap between "last tag observed" and "next tag expected" is the broken edge:

   Last tag observed	What broke	Look next at
   No Unpacking at the target hub	Message lost in routing	HIERARCHICAL_ROUTING_RESULT State
   Unpacking but no ROUTING_TO_LOCAL_EXECUTION	Deferred / buffered (init gate)	Deferring on-target / Buffering lines
   ROUTING_TO_LOCAL_EXECUTION but no handler logs	Handler threw on entry	An exception occurred during the processing of MessageDelivery
   Handler logged success, caller still hangs	Response never routed back	the o.ResponseFor(request) post + its Unpacking at the sender
   SubscribeAck then silence until a heartbeat	Initial Full dropped	owner-side echo filter / ChangedBy (see doc §"never sent the initial Full")
   type … is not registered in this hub's TypeRegistry	Type-registry mismatch	WithType(typeof(T), nameof(T)) on every hub the message transits

🚨 First, on a LIVE portal: is it even the new code? The grain serves what it activated with

Before tracing anything against a running mesh, rule out the cheapest cause there is. "The grain keeps serving old state until we send a dispose request" (maintainer, 2026-09-17): a per-node hub binds its configuration ONCE while activating and is then pinned by address — routing never resolves that path again. Every change a portal absorbs while it keeps running — a package installed or updated, a NodeType recompiled in place, a sync landing new source — changes what the NEXT activation would load; an address already up answers from what it bound, promptly and wrongly, with no error, no log line and nothing to grep. (A pod restart or a roll ends the activations it replaces, so those are not the stale case.)

So a fix that "did not take" on a live portal is as likely to be an un-recycled activation as a defect. Recycle the address — hub.RecycleNode(path, reason: "…"), or the recycle verb (MCP tool, the node's Recycle menu entry, mw recycle <path>) — and exercise it again before you spend an hour on a trace. On a NodeType the operator verb also stamps a FORCED release, which skips prebuilt adoption and compiles the live source (#2818); hub.RecycleNode, and a recycle of any ordinary node, compile nothing.

🚨 But a recycle makes the activation RE-READ; it does not decide what the re-read FINDS. If the second attempt answers the same way, the activation was never the problem and a third recycle will find nothing: a dispose-only recycle re-resolves the same store key (nodeTypePath, version) and re-binds the same local copy (#2471 — measured over 30+ minutes and six recycles, every surface reporting success). At that point go and read what the pod actually loaded ([ModuleLoad] … (written=…)), not the message flow. Full reference: StaleStateUntilRecycle.md.

🚨 A TEST is not automatically exempt. A fixture that builds and tears down its own mesh is; a SHARED one is not — an Orleans TestCluster per xUnit collection keeps activations between tests, so "the grain caches its config, Test B activates a different node at the same path, reads stale state from Test A". Disposing the hubs a test created is half of TestStateIsolation.md.

Read the DURATION first — it separates a hang from a real failure

Before any tracing, look at how long the failing case took. This is the cheapest signal there is and it is decisive:

Duration	What it is
seconds	a REAL assertion failure — the code ran and produced a wrong answer
minutes, no assertion output	a HANG — something never arrived and the harness timed out

Observed 2026-07-28 on the education suite: 251 tests, 6 failures, every one of them 1-3.5 minutes with no assertion text, while the one genuine content bug in the same suite failed in 2.4s. Six multi-minute failures across four different courses were ONE broken edge wearing six hats — not six bugs, and not "flaky tests to retry".

🚨 Do not read a slow failure as "the CI runner is slow". That reading is seductive (it even explains the durations) and it is how this class hides: a bigger timeout or a beefier runner makes it rarer without fixing anything, so it comes back later and less reproducibly. Same-machine proof that load was NOT the cause: the portal answered /health in 6 ms while the hang still reproduced — the identical suite had shown 5.1 s under genuine load earlier that day.

Retry belongs in the CALLER, never in the shared cache

Once you find a transient NotFound / DeliveryFailureException, the obvious fix — "resubscribe automatically at the stream layer" — is the one that has already taken production down twice. Do not write it.

• MeshNodeStreamCache is deliberately evict-only: its negative entry EXPIRES and the next natural read re-probes. Its own comment is explicit — "Self-healing, NEVER a watchdog … an auto-resubscribe watchdog is exactly what caused the 2026-06-08 prod outage; this only ever evicts, never re-subscribes."
• Unbounded caller-side retry is the OTHER outage: "resubscribing forever to an inexistent address produced an endless [ROUTE] NotFound message storm that burned a core and wedged the partition's hub" (production, 2026-06-14).

So the shape that is actually safe is the one MeshWeaver.Layout/AreaStreamRetry already implements: bounded retries, exponential backoff on Observable.Timer (never Task.Delay), a caller-supplied shouldRetry predicate, and the last error surfaced after giving up so the UI reports a real failure instead of spinning. It is wired for layout-area streams; a caller on another stream type needs the same wrapper, not a new mechanism and not a change to the cache.

A green CI badge is not a green suite

Check the JOBS, not the run conclusion. A job marked continue-on-error: true fails while its workflow still reports success — observed 2026-07-28: Education Content CI green with 3/3 e2e shards red, which is how the hang above sat unnoticed. Before trusting a gate, confirm it can actually fail:

gh run view <run-id> --json jobs --jq '.jobs[] | "\(.conclusion)\t\(.name)"'

Is it a lock, or a missed observation? (they look identical from the outside)

Most "deadlocks" in this codebase are not locks — they are a reactive emission that nobody observed. Tell them apart before you go hunting for a lock:

• Real lock-deadlock — one large gap mid-work where nothing runs, then timeout. The action block is wedged on a blocking continuation (await / .Result / .Wait() / SemaphoreSlim on a hub turn or grain turn).
• Missed observation — a burst of work for seconds, then total silence for the rest of the timeout. The work finished; the thing waiting on it never saw the terminal state.

Confirm with stacks mid-freeze — decisive in one shot:

pid=$(pgrep -f testhost | head -1)
dotnet-stack report -p $pid > /tmp/stacks.txt
grep -vE "System\.|Microsoft\.|xunit|testhost" /tmp/stacks.txt | sort -u   # any APP frame?

No MeshWeaver frame on any thread + total trace silence ⇒ a dropped reactive emission, not a lock. (Idle cores + silence is never a hot loop.)

The usual broken edges (root causes, not band-aids)

• One-shot-with-give-up: stream.Take(1).Timeout(15s).Subscribe(...) — the loaded-state emission arrives late or is dropped on the subscribe handshake, Timeout fires onError, the recovery gives up and never retries → the node stays non-terminal forever. Fix: re-establish, never give up (re-subscribe on fault); never Timeout-then-give-up on a lifecycle observer.
• Lost-on-reactivation: the observer lived only in the grain/agent-loop that set it up; on Orleans deactivate→reactivate (or hub re-init) it's gone and is never rebuilt. Fix: rebuild the observation on init; re-observe the existing child, don't re-run the loop and re-delegate.
• Cross-hub write under the wrong identity: a cold cross-hub stream.Update whose side effect runs on the emission thread where the inbound AccessContext was wiped → posts a NULL context, fails closed at the sender, the patch never reaches the owner, the wait never settles. Fix: Observable.Using(() => AccessContextScope.AsSystem(...), _ => stream.Update(...)) so the identity survives the Subscribe.
• Owner never sent the initial Full: SubscribeAck routed, then ~one heartbeat of dead silence. The echo filter dropped the Full or ChangedBy collapsed to empty. Fix on the owner side, never the caller.

When you've found it

Fix the broken edge — never the timeout (the user's standing rule: a bigger timeout "will just hang longer"). Leave the LogTrace/LogDebug lines you relied on in place (they cost nothing at higher levels and are how the next analogous hang gets debugged). If you genuinely need a stopgap before the real fix lands, say so explicitly and then fix the root cause.