From 3adf9f7ebc52f813104879b3ff3458269b2aa6bc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Roland=20B=C3=BCrgi?= Date: Sun, 9 Aug 2026 14:01:27 +0200 Subject: [PATCH] =?UTF-8?q?Test=20logging=20died=20in=20an=20async=20lifec?= =?UTF-8?q?ycle=20hook=20=E2=80=94=20every=20Monolith=20ILogger=20line=20w?= =?UTF-8?q?as=20dropped?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The #993 diagnostic emitted nothing on CI even after #997 repaired the appsettings copy race, because the sink downstream of it was closed. XUnitFileLogger.Log drops a record unless XUnitFileOutputHelper.IsInTestMethod() is true, and the only writer of that flag is AutoTestLoggingAttribute.Before via the XUnitFileOutputRegistry AsyncLocal. TestBase registered itself from InitializeAsync — and MonolithMeshTestBase overrides that hook as async. An AsyncLocal written inside an async method lives in that method's copied ExecutionContext and is discarded when it returns, so the registry was EMPTY by the time xUnit ran Before: SetCurrentTestMethod was never called, the flag stayed false for the whole test, and EVERY ILogger record of EVERY MonolithMeshTestBase test was silently dropped — at every level, on every platform, for the whole suite. The visible tell is the missing "=== TEST START: … ===" marker in the captured Output. A/B on two otherwise identical TestBase subclasses, differing only in whether InitializeAsync is async: sync → registry non-null, IsInTestMethod=True, Debug line present async → registry NULL, IsInTestMethod=False, Debug line absent IsEnabled(Debug) was true in BOTH — the config was fine, the level filter was fine, the sink was shut. Fix: register from the constructor, which runs synchronously on the runner's own flow so the write survives — which is what the registry's own doc comment always claimed ("the value set in a test's ctor flows to its method"). With it, ActivityTrackingHubTest now emits the whole landing path in order — TrackActivity ENTER → SyncedQuery Opening/Initial → onboard-gate storage read → CREATE → Write → change=Added → the poll's WalkLevel — so the next CI occurrence of #993 shows WHICH stage stalled instead of a bare timeout. Pinned by TestOutputLoggingLifecycleTest: one test asserts the sink is open under an async InitializeAsync (both assertions fail against the old code), the other asserts this project's Debug channels actually resolve to Debug. #979/#997 guard the config reaching $(TargetDir) at build time; this guards the sink at run time — a diagnostic needs both halves. Cost, measured: MeshWeaver.Query.Test is the only project with Debug channels, and its trx goes from a few KB to 33 MB (1.8 MB at the workflow's compression-level 9, 15-day retention). 83% of that is MeshWeaver.Hosting.Persistence.Query.StorageAdapterMeshQueryProvider plus MeshWeaver.Graph.SyncedQuery across all 363 tests. Every other project is Warning-only, so it gains only warnings and errors — which is the point. Worth narrowing those two channels once #993 is closed. Refs #993 Co-Authored-By: Claude Opus 5 (1M context) --- src/MeshWeaver.Fixture/TestBase.cs | 30 +++++++- .../XUnitFileOutputHelper.cs | 11 +++ .../TestOutputLoggingLifecycleTest.cs | 75 +++++++++++++++++++ 3 files changed, 112 insertions(+), 4 deletions(-) create mode 100644 test/MeshWeaver.Query.Test/TestOutputLoggingLifecycleTest.cs diff --git a/src/MeshWeaver.Fixture/TestBase.cs b/src/MeshWeaver.Fixture/TestBase.cs index 01680b26f9..4e9f429540 100644 --- a/src/MeshWeaver.Fixture/TestBase.cs +++ b/src/MeshWeaver.Fixture/TestBase.cs @@ -26,6 +26,28 @@ protected TestBase(ITestOutputHelper output) Output = output; FileOutput = new XUnitFileOutputHelper(output, GetType().Name); + // 🚨 Register HERE, in the constructor — not in InitializeAsync. + // + // XUnitFileOutputRegistry is backed by an AsyncLocal, and an AsyncLocal written + // inside an `async` method is confined to that method's copied ExecutionContext: + // it is DISCARDED when the method returns. MonolithMeshTestBase overrides + // InitializeAsync as `async` (it awaits hosted-service starts and access setup), + // so registering from base.InitializeAsync() left the registry EMPTY by the time + // xUnit invoked AutoTestLoggingAttribute.Before. Before therefore never called + // SetCurrentTestMethod, XUnitFileOutputHelper.IsInTestMethod() stayed false for + // the whole test, and XUnitFileLogger.Log dropped EVERY record — so no ILogger + // line from any MonolithMeshTestBase test ever reached xUnit's captured output, + // at any level, on any platform. That is why the Debug channels added to + // test/MeshWeaver.Query.Test/appsettings.json to diagnose #993 emitted nothing + // even after #997 fixed the appsettings copy race: the file was landing, the + // level filter said enabled, and the sink was closed. + // + // The constructor runs synchronously on the runner's own flow, so the write + // survives to Before — which is what the registry's own doc comment always + // claimed ("the value set in a test's ctor flows to its method"). Pinned by + // TestOutputLoggingLifecycleTest. + XUnitFileOutputRegistry.Register(this, FileOutput); + // Configure file logging integration. Log-level filters are bound // from appsettings.json in ServiceSetup (see ServiceSetup.CreateServiceCollection // → logging.AddConfiguration("Logging")). Flip the shared @@ -50,10 +72,10 @@ public virtual ValueTask InitializeAsync() { Initialize(); SetOutputHelper(FileOutput); - - // Register this test instance for cross-class access - XUnitFileOutputRegistry.Register(this, FileOutput); - + + // (Registration happens in the constructor — see the note there. Doing it from + // here is what broke test logging for every async-InitializeAsync test base.) + // Get logger after service provider is built _logger = ServiceProvider.GetService(typeof(ILogger)) as ILogger; diff --git a/src/MeshWeaver.Fixture/XUnitFileOutputHelper.cs b/src/MeshWeaver.Fixture/XUnitFileOutputHelper.cs index 25b6e2cb51..fa08e76e32 100644 --- a/src/MeshWeaver.Fixture/XUnitFileOutputHelper.cs +++ b/src/MeshWeaver.Fixture/XUnitFileOutputHelper.cs @@ -13,6 +13,17 @@ namespace MeshWeaver.Fixture; /// never see each other's helper (the parallel-safe replacement for the former /// process-wide ConcurrentDictionary<object, …>; see NoStaticState.md). The /// value set in a test's ctor flows to its method and any awaited continuations. +/// +/// 🚨 Register from the CONSTRUCTOR, never from an async lifecycle hook. +/// An assignment made inside an async method lives in that +/// method's copied ExecutionContext and is discarded the moment it returns — the caller +/// never observes it. TestBase.InitializeAsync used to do the registration, and +/// MonolithMeshTestBase overrides that hook as async; the registry was therefore +/// EMPTY when xUnit ran , so +/// was never called and +/// silently dropped every log record of every Monolith test. +/// The constructor runs synchronously on the runner's own flow, so its write survives. +/// Pinned by TestOutputLoggingLifecycleTest. /// public static class XUnitFileOutputRegistry { diff --git a/test/MeshWeaver.Query.Test/TestOutputLoggingLifecycleTest.cs b/test/MeshWeaver.Query.Test/TestOutputLoggingLifecycleTest.cs new file mode 100644 index 0000000000..97c06b95fa --- /dev/null +++ b/test/MeshWeaver.Query.Test/TestOutputLoggingLifecycleTest.cs @@ -0,0 +1,75 @@ +using System.Collections.Immutable; +using MeshWeaver.Fixture; +using MeshWeaver.Hosting.Monolith.TestBase; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace MeshWeaver.Query.Test; + +/// +/// Pins the TEST-LOG SINK itself — the thing every CI-only flake investigation depends on and +/// nobody checks, because a dead sink looks exactly like "the code logged nothing". +/// +/// What broke. XUnitFileLogger.Log drops a record unless +/// XUnitFileOutputHelper.IsInTestMethod() is true, and the only writer of that flag is +/// AutoTestLoggingAttribute.Before → XUnitFileOutputRegistry.GetAnyActiveOutputHelper(). +/// That registry is an , and the registration used to happen inside +/// TestBase.InitializeAsync. overrides that hook as +/// async — and an AsyncLocal written inside an async method lives in that method's +/// copied ExecutionContext and is discarded when it returns. So the registry was empty by +/// the time xUnit ran Before, SetCurrentTestMethod was never called, and +/// every ILogger record of every Monolith test was silently dropped — at every level, on +/// every platform. The tell is the missing === TEST START: … === marker. +/// +/// What it cost. The Debug channels added to +/// test/MeshWeaver.Query.Test/appsettings.json to diagnose the #993 +/// ActivityTrackingHubTest flake produced no output for weeks. #997 repaired one half of +/// that (the appsettings copy race that let MSBuild land the shared Warning-only file instead of +/// the project-local one) and the channels STILL emitted nothing, because the sink downstream of +/// them was closed. Both halves have to hold for a diagnostic to reach CI, so both are pinned: +/// #979/#997 guard the config reaching $(TargetDir) at build time, this guards the sink at +/// run time. +/// +public class TestOutputLoggingLifecycleTest(ITestOutputHelper output) : MonolithMeshTestBase(output) +{ + /// + /// The lifecycle pin: a test class whose InitializeAsync is async (which + /// 's is) must still have a LIVE log sink by the time its + /// body runs. Both assertions were false before the registration moved to the constructor. + /// + [Fact(Timeout = 20_000)] + public void AsyncInitializeAsync_StillLeavesTheTestLogSinkOpen() + { + XUnitFileOutputRegistry.GetAnyActiveOutputHelper().Should().NotBeNull( + "the output-helper registry is an AsyncLocal — registering it from an `async` " + + "InitializeAsync discards the write, which leaves AutoTestLoggingAttribute.Before " + + "with nothing to mark and silently kills logging for the whole test"); + + FileOutput.IsInTestMethod().Should().BeTrue( + "XUnitFileLogger drops every record unless the helper is inside a test method; this " + + "flag being false is what made the #993 Debug channels emit nothing on CI"); + } + + /// + /// The channel pin: this project raises specific channels to Debug in its own + /// appsettings.json precisely to diagnose #993. Assert the level filter actually + /// resolves to Debug for the tracking channel — if the shared Warning-only appsettings ever + /// wins the copy again, or the project file loses its overrides, this fails loudly instead of + /// producing another silent, evidence-free CI run. + /// + [Fact(Timeout = 20_000)] + public void ActivityTrackingDebugChannel_IsActuallyEnabled() + { + var factory = Mesh.ServiceProvider.GetRequiredService(); + foreach (var channel in ImmutableList.Create( + "MeshWeaver.Graph.ActivityTracking", + "MeshWeaver.Hosting.MeshNodeStreamCache")) + { + factory.CreateLogger(channel).IsEnabled(LogLevel.Debug).Should().BeTrue( + $"'{channel}' is raised to Debug in test/MeshWeaver.Query.Test/appsettings.json " + + "for the #993 investigation; a Warning-only config here means the diagnostic is " + + "dead again"); + } + } +}