AsyncLocal<T> is the mechanism behind ambient context in this codebase — the user's
AccessContext, the active test's output helper, the resolved locale. It is not a variable that
"just works everywhere". It is a slot in the ExecutionContext, and the .NET runtime's rules for
when that context is copied and when a copy is discarded decide whether your write is visible to the
code you expect.
Two rules cover every mistake made with it here:
1. A write survives only forward, along the flow that made it. A continuation scheduled on a different scheduler — a hub action block, an Orleans grain turn, an Rx scheduler, a thread-pool callback — starts from whatever
ExecutionContextit captured, which may be one where your slot was never set. The value is not "lost"; it was never in that flow.2. A write made inside an
asyncmethod is discarded when the method returns. Entering anasyncmethod copies theExecutionContext; assignments to anAsyncLocalland in the copy, and the copy dies with the method. The caller never observes it.
Rule 2 is the one that surprises people, because the code reads as if it obviously works.
The shape that costs you your instruments
// ❌ The write lands in InitializeAsync's COPIED ExecutionContext and is gone on return.
public virtual async ValueTask InitializeAsync()
{
await StartHostedServices();
SomeRegistry.Register(this, FileOutput); // AsyncLocal assignment
}
TestBase registered its xUnit output helper exactly like that, and MonolithMeshTestBase
overrides InitializeAsync as async (it awaits hosted-service starts and access-rights setup).
XUnitFileOutputRegistry is backed by an AsyncLocal<XUnitFileOutputHelper?>, so by the time xUnit
ran AutoTestLoggingAttribute.Before the registry was empty, SetCurrentTestMethod was never
called, XUnitFileOutputHelper.IsInTestMethod() stayed false for the whole test — and
XUnitFileLogger.Log dropped every record of every MonolithMeshTestBase test, at every level, on
every platform.
For two weeks that read as evidence of absence: the diagnostic channels people had added produced nothing, so the thing being diagnosed looked like it was not happening.
The tell, and it is a good one. The A/B between an otherwise identical sync and async
InitializeAsync:
sync InitializeAsync |
async InitializeAsync |
|
|---|---|---|
GetAnyActiveOutputHelper() |
non-null | null |
IsInTestMethod() |
true |
false |
logger.IsEnabled(Debug) |
true |
true |
the === TEST START: … === marker |
present | absent |
a Debug line in the output |
present | absent |
IsEnabled(Debug) is true in both. A live level check plus no output is not a configuration
problem — it is a closed sink. If you are turning log levels up and still getting nothing, stop
adjusting configuration and check whether the marker your harness writes is there at all.
The fix: register from the constructor
// ✅ The constructor runs synchronously on the runner's own flow, so the write survives
// into the test method and into every continuation that descends from it.
protected TestBase(ITestOutputHelper output)
{
…
XUnitFileOutputRegistry.Register(this, FileOutput);
}
That is what XUnitFileOutputRegistry's own contract always claimed — "the value set in a test's
ctor flows to its method and any awaited continuations" — and it can never go back into a lifecycle
hook. A comment at the call site says so, because the move looks arbitrary otherwise.
Instance 2 — silo-side ILogger is unreliable in Orleans tests
AddXUnitLogger() called with no accessor registers a fresh TestOutputHelperAccessor singleton
in whatever container it is called on:
if (outputHelperAccessor == null)
builder.Services.AddSingleton<TestOutputHelperAccessor>(); // fresh, and nothing populates it
A silo built by ConfigureLogging(logging => logging.AddXUnitLogger()) therefore gets its own
accessor, while ServiceSetup.SetOutputHelper only ever populates the test's provider. So
XUnitLogger.Log falls through to its second source:
var outputHelper = testOutputHelperAccessor.OutputHelper
?? XUnitFileOutputRegistry.GetAnyActiveOutputHelper(); // ← the AsyncLocal
if (outputHelper == null)
return; // silently
…and that AsyncLocal is empty on any thread whose ExecutionContext does not descend from the test
class's constructor: the Orleans grain scheduler, timers, and pool threads. This is rule 1 rather
than rule 2, but it lands in exactly the same place — a LogInformation that runs and produces no
output.
The consequence is a working rule, not just a curiosity:
Diagnose silo-side code with a file-based trace, never
LogInformation. A gap in an Orleans test's silo log carries no information. In one investigation a file trace recorded the enrichment running squarely inside a "45 seconds of complete silence" window whose silo log contained two lines, neither of them theLogInformationcalls that had just executed.
One half of this is now repaired: a FAULT survives, an Information line still does not (#2495)
XUnitLogger.Log writes a record carrying an exception at Warning or worse to
TestTraceLog before it consults the output helper, exactly as
XUnitFileLogger already did. So a silo-side exception now reaches the one file CI keeps even on a
grain-scheduler thread with an empty AsyncLocal. It was not doing this, and the asymmetry was
expensive: the two loggers split the process by service provider, not by importance —
XUnitFileLogger serves the TestBase container, XUnitLogger serves everything built by a HOST,
which in an Orleans test is the silo, the client, and every mesh hub and grain inside them. Measured
on CI run 33062668925: the Orleans host ran 208 tests over 272 s and wrote 4 lines to that file,
against 819 / 606 / 1789 from its three Monolith-derived shard-mates. With the fault sink wired, the
same suite writes 129.
The rule above is unchanged for everything else. A silo-side LogInformation, LogDebug, or a
LogWarning with no exception still reaches nothing when the helper is absent — so a gap in a silo
log still carries no information. What you may now read as evidence is the presence of a fault
record, not the absence of anything.
Reading that silence as "the request never reached the grain" is what sent a previous session down the wrong path entirely; a message trace showed routing, activation, subscribe, ack and the render round-trip all completing in ~260 ms.
The framework gets this right where it matters — copy that pattern
LayoutAreaHost needs the subscriber's identity during a render that happens on a different
scheduler entirely. It does the only thing that works: capture at construction, restore on the
scope that needs it.
// ctor — runs on the subscriber's flow, where the AsyncLocal is live.
var capturedAccessContext = accessService?.Context;
…
.WithInitialization(_ => BuildInitialization(
context, isDefaultArea, resolvedArea, accessService, capturedAccessContext, ctorLogger))
// BuildInitialization — runs later, on the render scheduler, where the AsyncLocal is empty.
if (capturedAccessContext != null)
accessService?.SetContext(capturedAccessContext);
…
// and it is CLEARED on teardown, so the scope does not leak into the next thing on that thread.
Three properties make it correct, and all three are required:
- The capture happens where the value is live — synchronously, in the constructor, on the subscriber's own flow.
- The restore happens on the scope that consumes it, not somewhere convenient upstream.
- The scope is cleared on teardown. A restored ambient value on a pooled thread outlives the work that needed it otherwise.
This is the same mechanism CarryAccessContext applies to every framework write primitive so
.Subscribe(...) callbacks run under the calling user — see
AccessContext Propagation.
The rule, applied
Writing to an AsyncLocal:
- Write from a synchronous frame on the flow whose continuations must observe it — a
constructor, a synchronous setter, a
usingscope. Never from inside anasyncmethod that returns before the observers run. - If the value must survive a scheduler hop, that is not an
AsyncLocalproblem to solve — it is a capture-and-restore problem. Capture into a local or a field at the point of truth and restore explicitly on the far side.
Reading from an AsyncLocal:
- Never read one on a hub action block, a grain turn, an Rx scheduler callback, a timer, or a pool
thread and treat the result as authoritative. Read it from the message or the captured
value instead:
delivery.AccessContext,AccessContext.Locale, a captured field. - 🚨 The localisation rule is a direct instance of this: never resolve from
CultureInfo.CurrentUICulture, because a layout-area render hops the hub scheduler and an ambient culture does not survive it — one user's UI would pick up another user's language. Resolution is always explicit offAccessContext.Locale. See Localization.
Reviewing a diagnostic that produces nothing:
- Check for the harness's own marker before adjusting any level. Present marker + no lines is a level problem; absent marker is a closed sink, and no amount of configuration will open it.
- On the silo side, do not treat missing log lines as evidence at all. Write a file trace.
Pinned by
TestOutputLoggingLifecycleTest guards both halves of "a diagnostic reaches CI":
| Test | What it holds |
|---|---|
AsyncInitializeAsync_StillLeavesTheTestLogSinkOpen |
the run-time half — both assertions fail against the pre-fix registration point (that is the A/B table above) |
ActivityTrackingDebugChannel_IsActuallyEnabled |
the configuration half, complementing the build-time $(TargetDir) guards |
See also
- AccessContext Propagation — the identity baton: how the framework carries
AccessContextacross exactly these hops, and what happens when it does not. - Localization — why locale resolution is explicit off
AccessContext.Localeand never ambient. - Orleans Task Scheduler — which schedulers your continuation can land on.
- Writing Tests — the harness this instance broke, and how test logging is wired.
- Debugging Message Flow — the trace surface to use when
ILoggeris not trustworthy.