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"); + } + } +}