Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
30 changes: 26 additions & 4 deletions src/MeshWeaver.Fixture/TestBase.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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<TestBase>)) as ILogger<TestBase>;

Expand Down
11 changes: 11 additions & 0 deletions src/MeshWeaver.Fixture/XUnitFileOutputHelper.cs
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,17 @@ namespace MeshWeaver.Fixture;
/// never see each other's helper (the parallel-safe replacement for the former
/// process-wide <c>ConcurrentDictionary&lt;object, …&gt;</c>; see NoStaticState.md). The
/// value set in a test's ctor flows to its method and any awaited continuations.
///
/// <para>🚨 <b>Register from the CONSTRUCTOR, never from an <c>async</c> lifecycle hook.</b>
/// An <see cref="AsyncLocal{T}"/> assignment made inside an <c>async</c> method lives in that
/// method's copied <c>ExecutionContext</c> and is discarded the moment it returns — the caller
/// never observes it. <c>TestBase.InitializeAsync</c> used to do the registration, and
/// <c>MonolithMeshTestBase</c> overrides that hook as <c>async</c>; the registry was therefore
/// EMPTY when xUnit ran <see cref="AutoTestLoggingAttribute.Before"/>, so
/// <see cref="XUnitFileOutputHelper.SetCurrentTestMethod"/> was never called and
/// <see cref="XUnitFileLogger"/> 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 <c>TestOutputLoggingLifecycleTest</c>.</para>
/// </summary>
public static class XUnitFileOutputRegistry
{
Expand Down
75 changes: 75 additions & 0 deletions test/MeshWeaver.Query.Test/TestOutputLoggingLifecycleTest.cs
Original file line number Diff line number Diff line change
@@ -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;

/// <summary>
/// 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".
///
/// <para><b>What broke.</b> <c>XUnitFileLogger.Log</c> drops a record unless
/// <c>XUnitFileOutputHelper.IsInTestMethod()</c> is true, and the only writer of that flag is
/// <c>AutoTestLoggingAttribute.Before</c> → <c>XUnitFileOutputRegistry.GetAnyActiveOutputHelper()</c>.
/// That registry is an <see cref="AsyncLocal{T}"/>, and the registration used to happen inside
/// <c>TestBase.InitializeAsync</c>. <see cref="MonolithMeshTestBase"/> overrides that hook as
/// <c>async</c> — and an AsyncLocal written inside an <c>async</c> method lives in that method's
/// copied <c>ExecutionContext</c> and is discarded when it returns. So the registry was empty by
/// the time xUnit ran <c>Before</c>, <c>SetCurrentTestMethod</c> was never called, and
/// <b>every ILogger record of every Monolith test was silently dropped</b> — at every level, on
/// every platform. The tell is the missing <c>=== TEST START: … ===</c> marker.</para>
///
/// <para><b>What it cost.</b> The Debug channels added to
/// <c>test/MeshWeaver.Query.Test/appsettings.json</c> to diagnose the #993
/// <c>ActivityTrackingHubTest</c> 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 <c>$(TargetDir)</c> at build time, this guards the sink at
/// run time.</para>
/// </summary>
public class TestOutputLoggingLifecycleTest(ITestOutputHelper output) : MonolithMeshTestBase(output)
{
/// <summary>
/// The lifecycle pin: a test class whose <c>InitializeAsync</c> is <c>async</c> (which
/// <see cref="MonolithMeshTestBase"/>'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.
/// </summary>
[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");
}

/// <summary>
/// The channel pin: this project raises specific channels to Debug in its own
/// <c>appsettings.json</c> 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.
/// </summary>
[Fact(Timeout = 20_000)]
public void ActivityTrackingDebugChannel_IsActuallyEnabled()
{
var factory = Mesh.ServiceProvider.GetRequiredService<ILoggerFactory>();
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");
}
}
}
Loading