Logging from WebApplicationFactory can no longer be captured in 2.2.9

[jvandertil]

Description

We are developing a ASP.NET Core application and for testing we use the ASP.NET Core TestHost (WebApplicationFactory) to facilitate integration testing.
To capture the logging we replace the ILoggerFactory with an implementation that uses the TestContext to write the application logging so it can be used for debugging if tests fail.

Since version 2.2.9 logging is no longer reliably captured.

Steps to reproduce

1. Download this example solution: TestOutputTest.zip
2. Run the test
3. Check the TestContext messages, all the logging output for the request is missing.
   As a test I added a "Hello from Get" message to the controller, which is also not visible.

Expected behavior

All the messages passed to the TestContext for a single test are captured.
If MSTest.TestAdapter and MSTest.TestFramework version 2.2.8 are used the output is captured as expected

Actual behavior

Messages are missing, probably because they are in a different async context.

Environment

.NET SDK 6.0.202
Windows 11
Visual Studio 2022 (17.1.4)
MsTest 2.2.9

Also tried using the pre-release version 2.2.10-preview-20220414-01, but same issue there.

[patricsjoo]

Not work in 2.2.10 either.

[jvandertil]

SInce this issue is not getting any attention / responses I have decided to workaround this by using file logging through Serilog and attaching the generated log file to the TestContext.

[vaganovk]

Fixed similar issue by adding TestServer.PreserveExecutionContext = true; before WebApplicationFactory.CreateClient() call.

The root cause seems to be:

1. MSTest collects test output via AsyncLocal-based string builder, see

   testfx/src/Adapter/PlatformServices.Shared/netstandard1.3/Services/ns13ThreadSafeStringWriter.cs

   Line 20 in 4a1e386

   private static readonly AsyncLocal<Dictionary<string, ThreadSafeStringBuilder>> State = new AsyncLocal<Dictionary<string, ThreadSafeStringBuilder>>();

   - so when execution context changes, logs get captured into different destination (which then gets ignored after test completes).
2. By default, TestServer does not preserve execution context between client and server calls for a purpose: [Discussion] TestServer no longer preserves ExecutionContext and AsyncLocals between client and server dotnet/aspnetcore#10134

Capturing test results into separate file and adding it to TestContext seems to be even better option as the intent of PreserveExecutionContext = false was to improve test isolation.

[gaurav137]

We hit this issue too. We use the test context in a similar manner as jvandertil described in the sample. Our codebase was moving to .NET 6 and we took the opportunity to move to latest version of various nuget packages and picked up this issue with v2.2.10. Took us hours to figure out why our test logs were missing logs and once we root caused it we found this issue was reported already.

@jvandertil we worked around this for now by using a BufferBlock and instead of doing a testContext.WriteLine(message) we now do BufferBlock.Post(message). Then the logs are actually written to by Task.Run() which is running under an execution context that we are in better control of under test. So to take your attached sample it would go something like:

   [DebuggerStepThrough]
   internal class MsTestLogger : ILogger
   {
       private readonly BufferBlock<string> _logs;
       private readonly TestContext _context;
       private readonly string _categoryName;

       public MsTestLogger(TestContext context, string categoryName)
       {
           _context = context ?? throw new ArgumentNullException(nameof(context));
           _categoryName = categoryName;
           _logs = new BufferBlock<string>();

           // Workaround for the AsyncLocal issue. Assumption being invocation of this constructor captures
           //  the right execution context that is unaffected by code under test where we cannot assume that
           // execution context gets preserved when Log() gets invoked.
           TaskFactory.Run(async () =>
           {
               while (await _logs.OutputAvailableAsync())
               {
                   string message = await _logs.ReceiveAsync();
                   _context.WriteLine(message);
               }
           }
       }

       public IDisposable BeginScope<TState>(TState state)
       {
           return NoopDisposable.Instance;
       }

       public bool IsEnabled(LogLevel logLevel)
           => true;

       public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
       {
           _logs.Post($"{logLevel}: {_categoryName} [{eventId}] {formatter(state, exception)}");

           if (exception is not null)
           {
               _logs.Post(exception.ToString());
           }
       }

       private class NoopDisposable : IDisposable
       {
           public static readonly NoopDisposable Instance = new NoopDisposable();

           public void Dispose()
           {
           }
       }
   }
}

This way we avoided the Serilog dependency to keep the workaround minimal. Hope this helps.

[Evangelink]

I confirm that there is a big difference of output between MSTest < 2.2.9 and above.

Before:

TestContext Messages:
Debug: Microsoft.AspNetCore.Mvc.ModelBinding.ModelBinderFactory [RegisteredModelBinderProviders] Registered model binder providers, in the following order: Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BinderTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ServicesModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.HeaderModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FloatingPointTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.EnumTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.DateTimeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.SimpleTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CancellationTokenModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ByteArrayModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormFileModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormCollectionModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.KeyValuePairModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.DictionaryModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ArrayModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CollectionModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ComplexObjectModelBinderProvider
Debug: Microsoft.Extensions.Hosting.Internal.Host [Starting] Hosting starting
Debug: Microsoft.AspNetCore.Hosting.Diagnostics [HostingStartupAssemblyLoaded] Loaded hosting startup assembly WebApplication1
Debug: Microsoft.Extensions.Hosting.Internal.Host [Started] Hosting started
Information: Microsoft.AspNetCore.Hosting.Diagnostics [1] Request starting HTTP/1.1 GET http://localhost/WeatherForecast - -
Debug: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware [WildcardDetected] Wildcard detected, all requests with hosts will be allowed.
Trace: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware [AllHostsAllowed] All hosts are allowed.
Debug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher [CandidatesFound] 1 candidate(s) found for the request path '/WeatherForecast'
Debug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher [CandidateValid] Endpoint 'WebApplication1.Controllers.WeatherForecastController.Get (WebApplication1)' with route pattern 'WeatherForecast' is valid for the request path '/WeatherForecast'
Debug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware [MatchSuccess] Request matched endpoint 'WebApplication1.Controllers.WeatherForecastController.Get (WebApplication1)'
Debug: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware [EndpointMatched] Static files was skipped as the request already matched an endpoint.
Warning: Microsoft.AspNetCore.HttpsPolicy.HttpsRedirectionMiddleware [FailedToDeterminePort] Failed to determine the https port for redirect.
Information: Microsoft.AspNetCore.Routing.EndpointMiddleware [ExecutingEndpoint] Executing endpoint 'WebApplication1.Controllers.WeatherForecastController.Get (WebApplication1)'
Information: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [ControllerActionExecuting] Route matched with {action = "Get", controller = "WeatherForecast"}. Executing controller action with signature System.Collections.Generic.IEnumerable`1[WebApplication1.WeatherForecast] Get() on controller WebApplication1.Controllers.WeatherForecastController (WebApplication1).
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [FilterExecutionPlan] Execution plan of authorization filters (in the following order): None
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [FilterExecutionPlan] Execution plan of resource filters (in the following order): None
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [FilterExecutionPlan] Execution plan of action filters (in the following order): Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter (Order: -3000), Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter (Order: -2000)
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [FilterExecutionPlan] Execution plan of exception filters (in the following order): None
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [FilterExecutionPlan] Execution plan of result filters (in the following order): Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter (Order: -2000)
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [ControllerFactoryExecuting] Executing controller factory for controller WebApplication1.Controllers.WeatherForecastController (WebApplication1)
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [ControllerFactoryExecuted] Executed controller factory for controller WebApplication1.Controllers.WeatherForecastController (WebApplication1)
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [BeforeExecutingMethodOnFilter] Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [AfterExecutingMethodOnFilter] Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [BeforeExecutingMethodOnFilter] Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [AfterExecutingMethodOnFilter] Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
Information: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [ActionMethodExecuting] Executing action method WebApplication1.Controllers.WeatherForecastController.Get (WebApplication1) - Validation state: Valid
Information: WebApplication1.Controllers.WeatherForecastController [0] Hello from Get
Information: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [ActionMethodExecuted] Executed action method WebApplication1.Controllers.WeatherForecastController.Get (WebApplication1), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 1.0485ms.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [BeforeExecutingMethodOnFilter] Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [AfterExecutingMethodOnFilter] Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [BeforeExecutingMethodOnFilter] Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [AfterExecutingMethodOnFilter] Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [BeforeExecutingMethodOnFilter] Result Filter: Before executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [AfterExecutingMethodOnFilter] Result Filter: After executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [BeforeExecutingActionResult] Before executing action result Microsoft.AspNetCore.Mvc.ObjectResult.
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.DefaultOutputFormatterSelector [RegisteredOutputFormatters] List of registered output formatters, in the following order: Microsoft.AspNetCore.Mvc.Formatters.HttpNoContentOutputFormatter, Microsoft.AspNetCore.Mvc.Formatters.StringOutputFormatter, Microsoft.AspNetCore.Mvc.Formatters.StreamOutputFormatter, Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonOutputFormatter
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.DefaultOutputFormatterSelector [NoAcceptForNegotiation] No information found on request to perform content negotiation.
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.DefaultOutputFormatterSelector [SelectingOutputFormatterWithoutUsingContentTypes] Attempting to select an output formatter without using a content type as no explicit content types were specified for the response.
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.DefaultOutputFormatterSelector [SelectingFirstCanWriteFormatter] Attempting to select the first formatter in the output formatters list which can write the result.
Debug: Microsoft.AspNetCore.Mvc.Infrastructure.DefaultOutputFormatterSelector [FormatterSelected] Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonOutputFormatter' and content type 'application/json' to write the response.
Information: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor [ObjectResultExecuting] Executing ObjectResult, writing value of type 'WebApplication1.WeatherForecast[]'.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [AfterExecutingActionResult] After executing action result Microsoft.AspNetCore.Mvc.ObjectResult.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [BeforeExecutingMethodOnFilter] Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
Trace: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [AfterExecutingMethodOnFilter] Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
Information: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker [ActionExecuted] Executed action WebApplication1.Controllers.WeatherForecastController.Get (WebApplication1) in 16.3132ms
Information: Microsoft.AspNetCore.Routing.EndpointMiddleware [ExecutedEndpoint] Executed endpoint 'WebApplication1.Controllers.WeatherForecastController.Get (WebApplication1)'
Information: Microsoft.AspNetCore.Hosting.Diagnostics [2] Request finished HTTP/1.1 GET http://localhost/WeatherForecast - - - 200 - application/json;+charset=utf-8 45.8921ms
Debug: Microsoft.Extensions.Hosting.Internal.Host [Stopping] Hosting stopping
Debug: Microsoft.Extensions.Hosting.Internal.Host [Stopping] Hosting stopping
Debug: Microsoft.Extensions.Hosting.Internal.Host [Stopped] Hosting stopped
Debug: Microsoft.Extensions.Hosting.Internal.Host [Stopped] Hosting stopped

After:

 TestContext Messages:
Debug: Microsoft.AspNetCore.Mvc.ModelBinding.ModelBinderFactory [RegisteredModelBinderProviders] Registered model binder providers, in the following order: Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BinderTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ServicesModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.HeaderModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FloatingPointTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.EnumTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.DateTimeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.SimpleTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CancellationTokenModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ByteArrayModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormFileModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormCollectionModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.KeyValuePairModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.DictionaryModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ArrayModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CollectionModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ComplexObjectModelBinderProvider
Debug: Microsoft.Extensions.Hosting.Internal.Host [Starting] Hosting starting
Debug: Microsoft.AspNetCore.Hosting.Diagnostics [HostingStartupAssemblyLoaded] Loaded hosting startup assembly WebApplication1
Debug: Microsoft.Extensions.Hosting.Internal.Host [Started] Hosting started
Debug: Microsoft.Extensions.Hosting.Internal.Host [Stopping] Hosting stopping
Debug: Microsoft.Extensions.Hosting.Internal.Host [Stopped] Hosting stopped
Debug: Microsoft.Extensions.Hosting.Internal.Host [Stopping] Hosting stopping
Debug: Microsoft.Extensions.Hosting.Internal.Host [Stopped] Hosting stopped

[jr01]

Our application takes some seconds to startup and in order to not incur this cost in each (parallel) integration test we share a static WebApplicationFactory between tests. This required a slightly different approach to the one outlined by @jvandertil and @gaurav137

At the start of each test we create a unique testId and link it to the test's TestContext and captured ExecutionContext.
When sending a request using HttpClient we transfer the testId in an X-TestId header to the server.
When logging we grab testId from from the X-TestId request header (using an injected HttpContextAccessor), or grab the testId from the running test (kept in an ambient AsyncLocal).
Then we use the testId to resolve the linked contexts and run the testContext.WriteLine from within the ExecutionContext.

public sealed class CustomWebApplicationFactory : WebApplicationFactory<Program>
{
    protected override void ConfigureWebHost(IWebHostBuilder builder)
    {
        builder.ConfigureLogging((context, loggingBuilder) =>
        {
            loggingBuilder.ClearProviders();
            loggingBuilder.AddProvider<TestContextLoggerProvider>();
        });

        builder.ConfigureServices(services =>
        {
            services.AddScoped<TestContextProvider>();
            services.AddSingleton<ILoggingSink, TestContextLoggingSink>();
            services.AddHttpContextAccessor();
        });
    }

    public IServiceScope CreateScope(TestContext testContext)
    {
        var scope = this.Services.CreateScope();
        var contextProvider = scope.ServiceProvider.GetRequiredService<TestContextProvider>();
        contextProvider.Register(testContext);
        return scope;
    }	
}

public interface ILoggingSink
{
    void WriteLine(string msg);
}

public static class LoggingBuilderExtensions
{
    public static ILoggingBuilder AddProvider<T>(this ILoggingBuilder builder)
        where T : class, ILoggerProvider
    {
        builder.Services.AddSingleton<ILoggerProvider, T>();
        return builder;
    }
}

public sealed class TestContextProvider : IDisposable
{
    private readonly static AsyncLocal<string?> ambientTestId = new();
    private readonly static ConcurrentDictionary<string, TestContextProvider> testContexts = new();

    public TestContext TestContext { get; private set; } = default!;
	
    public string TestId { get; private set; } = default!;

    public ExecutionContext ExecutionContext { get; private set; } = default!;

    public void Register(TestContext testContext)
    {
        this.TestContext = testContext;
        this.ExecutionContext = ExecutionContext.Capture()!;
        this.TestId = Guid.NewGuid().ToString();

        testContexts.TryAdd(this.TestId, this);
        ambientTestId.Value = this.TestId;
    }

    public static TestContextProvider Resolve(string? testId)
    {
        testId ??= ambientTestId.Value ?? throw new InvalidOperationException($"Call {nameof(Register)}");

        return testContexts[testId];
    }

    public void Dispose()
    {
        if (this.TestId is null)
        {
            throw new InvalidOperationException($"Call {nameof(Register)}");
        }

        testContexts.TryRemove(this.TestId, out _);
	ambientTestId.Value = null;
    }
}

public sealed class TestContextLoggingSink : ILoggingSink
{
    private readonly IHttpContextAccessor httpContextAccessor;

    public TestContextLoggingSink(
        IHttpContextAccessor httpContextAccessor)
    {
        this.httpContextAccessor = httpContextAccessor;
    }

    public void WriteLine(string msg)
    {
        string? testId = null;
        if (this.httpContextAccessor.HttpContext is not null)
        {
            if (!this.httpContextAccessor.HttpContext.Request.Headers.TryGetValue("X-TestId", out var testIds) || testIds.Count != 1)
            {
                throw new InvalidOperationException("HttpRequest must have exactly 1 X-TestId header");
            }

            testId = testIds[0];
        }

        var testContextProvider = TestContextProvider.Resolve(testId);

        ExecutionContext.Run(testContextProvider.ExecutionContext, (_) =>
        {
            testContextProvider.TestContext.WriteLine(msg);
        }, null);
    }
}

public sealed class TestContextLoggerProvider : ILoggerProvider
{ 
    private readonly TimeProvider timeProvider;
    private readonly ILoggingSink loggingSink;

    public TestContextLoggerProvider(TimeProvider timeProvider, ILoggingSink loggingSink)
    {
        this.timeProvider = timeProvider;
        this.loggingSink = loggingSink;
    }

    public ILogger CreateLogger(string categoryName)
    {
        return new TestContextLogger(this.timeProvider, this.loggingSink);
    }

    public void Dispose()
    {
    }

    private sealed class TestContextLogger : ILogger
    {
        private readonly TimeProvider timeProvider;
        private readonly ILoggingSink logSink;

        public TestContextLogger(TimeProvider timeProvider, ILoggingSink logSink)
        {
            this.timeProvider = timeProvider;
            this.logSink = logSink;
        }

        public IDisposable? BeginScope<TState>(TState state) where TState : notnull
        {
            return null;
        }

        public bool IsEnabled(LogLevel logLevel)
        {
            return logLevel != LogLevel.None;
        }

        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
        {
            var now = this.timeProvider.GetLocalNow();
            var msg = $"[{now:HH:mm:ss.fff} {logLevel}] {formatter(state, exception)}";

            this.logSink.WriteLine(msg);
            if (exception is not null)
            {
                this.logSink.WriteLine(exception.ToString());
            }
        }
    }
}

Usage with a shared CustomWebApplicationFactory:

[TestClass]
public class WeatherForecastControllerTest : IntegrationTest
{
    [TestMethod]
    public async Task Forecast()
    {
        var httpClient = this.CreateHttpClient();

        using var response = await httpClient.GetAsync("WeatherForecast");

        response.EnsureSuccessStatusCode();
    }
}

public abstract class IntegrationTest : IDisposable
{
    private static readonly CustomWebApplicationFactory webApplicationFactory = new();
    private bool disposedValue;

    public IServiceScope Scope { get; private set; } = default!;

    public TestContext TestContext { get; set; } = default!;

    [TestInitialize]
    public void TestInitialize()
    {
        this.Scope = webApplicationFactory.CreateScope(this.TestContext);
    }

    public void Dispose()
    {
        Dispose(true);
        GC.SuppressFinalize(this);
    }

    protected virtual void Dispose(bool disposing)
    {
        if (!this.disposedValue)
        {
            if (disposing)
            {
                this.Scope.Dispose();
                this.Scope = null!;
            }

            this.disposedValue = true;
        }
    }

    public HttpClient CreateHttpClient()
    {
        var httpClient = webApplicationFactory.CreateClient(new WebApplicationFactoryClientOptions
        {
        });

        var testId = this.Scope.ServiceProvider.GetRequiredService<TestContextProvider>().TestId;
        httpClient.DefaultRequestHeaders.Add("X-TestId", testId);

        return httpClient;
    }
}

Usage from an isolated test:

[TestClass]
public class IsolatedTest
{
    public TestContext TestContext { get; set; } = default!;

    [TestMethod]
    public async Task IsolatedTest01()
    {
        using var webApplicationFactory = new CustomWebApplicationFactory();

        using var testScope = webApplicationFactory.CreateScope(this.TestContext);

        var httpClient = webApplicationFactory.CreateClient(new WebApplicationFactoryClientOptions
        {
        });

        httpClient.DefaultRequestHeaders.Add("X-TestId", testScope.ServiceProvider.GetRequiredService<TestContextProvider>().TestId);

        using var response = await httpClient.GetAsync("WeatherForecast");
        response.EnsureSuccessStatusCode();
    }
}

I'm using latest .net 8

<Project Sdk="Microsoft.NET.Sdk">

  <PropertyGroup>
    <TargetFramework>net8.0</TargetFramework>
    <ImplicitUsings>enable</ImplicitUsings>
    <Nullable>enable</Nullable>

    <IsPackable>false</IsPackable>
    <IsTestProject>true</IsTestProject>

  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="Microsoft.AspNetCore.Mvc.Testing" Version="8.0.0" />
    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.8.0" />
    <PackageReference Include="MSTest.TestAdapter" Version="3.1.1" />
    <PackageReference Include="MSTest.TestFramework" Version="3.1.1" />
    <PackageReference Include="coverlet.collector" Version="6.0.0" />
  </ItemGroup>

  <ItemGroup>
    <ProjectReference Include="..\WebApplication1\WebApplication1.csproj" />
  </ItemGroup>

</Project>

[changov]

Thanks a lot, @jr01. I'm on the 6th hour of fighting this TestContext madness, and you saved me probably much more. This should really be fixed in test framework!

[JustusGreiberORGADATA]

We start a "real" web application with Kestrel for our UI tests and because Kestrel does not flow execution context from the servers startup to the connection accept loop I ran into the same problem:
https://github.com/dotnet/aspnetcore/blob/1d78a4c5f8149743629dc922db2ea27c0c53b543/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs#L27-L31

The standard console logger from Microsoft.Extensions.Logging seems to work though. If I understand everything correctly, this is more a coincidence than intended behavior. The console logger creates a thread to process messages when it is first instantiated:

https://github.com/dotnet/runtime/blob/8ccb71eadfc318017a78e1b7d356356dae5688a2/src/libraries/Microsoft.Extensions.Logging.Console/src/ConsoleLoggerProvider.cs#L58-L62

This thread is likely instantiated "early enough" because I resolve the logger during host startup (or because the host resolves it before starting Kestrel).

I think designing TestContext.WriteLine to rely on execution context might not be such a good idea and does lead to a pit of failure.
Instead a differentiation between the string builders might be more sensible.

The following (ThreadSafe)StringWriters should flow with ExecutionContext:
"out" -> Console.Out
"err" -> Console.Error
"trace" -> Debug.Write/Trace.Write (I think?)

The following StringWriters should not use ExecutionContext. Instead the single source of truth should be the TestContext instance:
"context" -> TestContext.WriteLine

[mstefarov]

I am also hitting this problem, with MSTest 3.5.2. We have an EventListener that logs to TestContext, and the Write calls come from whatever thread / async context the event was raised on. Many log messages are getting lots because of this "ThreadSafeStringWriter" quirk.

I'm guessing this behavior was originally designed to avoid mixing output from tests executing in parallel, but it doesn't make sense when parallel execution is off.

[Youssef1313]

The original repro works now in MSTest 3.10.4 (the latest at the time of writing this comment). So closing out.