I'm creating an integration test for a Web API, so I'm starting an entire application in a unit test using WebHost.CreateDefaultBuilder() and the usual setup bits.
While unit testing, my log framework writes to console to ease debugging of failing tests. However, console writing from within the application does not work. I see log before and after from the parts of the test that is not within the app. Currently I have to get around the issue by logging to file, but would be really nice if there was a way for console output to work.
Sadly with the nature of the integration test, a minimal reproduction isn't that minimal, but this reproduce the issue in 2 cases, and shows a working but very tedious workaround.
Project file with deps:
<Project Sdk="Microsoft.NET.Sdk">
<PropertyGroup>
<TargetFramework>net6.0</TargetFramework>
<LangVersion>10.0</LangVersion>
</PropertyGroup>
<ItemGroup>
<PackageReference Include="Microsoft.AspNetCore.Mvc.NewtonsoftJson" Version="3.1.24" />
<PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.1.0" />
<PackageReference Include="MSTest.TestAdapter" Version="2.2.10" />
<PackageReference Include="MSTest.TestFramework" Version="2.2.10" />
</ItemGroup>
</Project>
And the actual test implementation:
namespace Reproduce.Tests
{
using Microsoft.AspNetCore;
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.AspNetCore.Hosting.Server.Features;
using Microsoft.AspNetCore.Mvc;
using Microsoft.AspNetCore.Mvc.ApplicationParts;
using Microsoft.AspNetCore.Mvc.Controllers;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.VisualStudio.TestTools.UnitTesting;
using System;
using System.Collections.Generic;
using System.Linq;
using System.Net;
using System.Net.Http;
using System.Reflection;
using System.Threading;
using System.Threading.Tasks;
[TestClass]
public class ReproduceConsoleOutIssueTest
{
// A log class that logs through given LogAction if given, or directly on Console if not.
public class Logger
{
internal readonly List<string> RecordedLog = new();
internal Action<string> LogAction { get; set; }
internal void Log(string msg)
{
RecordedLog.Add(msg);
var action = LogAction ?? Console.Out.WriteLine;
action("INTERNAL LOGGING " + msg);
}
}
// A simple controller that tries to log
public class MyController : ControllerBase
{
private readonly Logger _log;
public MyController(Logger log) { _log = log; }
[Route("api/test"), HttpGet]
public string Test()
{
_log.Log("Test was called");
return "Yay";
}
}
internal class Startup
{
private class ControllerSelector : IApplicationFeatureProvider<ControllerFeature>
{
internal ICollection<TypeInfo> Controllers { get; init; }
public void PopulateFeature(IEnumerable<ApplicationPart> parts, ControllerFeature feature)
{
foreach (var c in Controllers) feature.Controllers.Add(c);
}
}
public void ConfigureServices(IServiceCollection services)
{
var mvcCoreBuilder = services.AddMvcCore();
mvcCoreBuilder.ConfigureApplicationPartManager(apm => apm.FeatureProviders.Add(
new ControllerSelector { Controllers = new[] { typeof(MyController).GetTypeInfo() }}
));
}
public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
app.UseRouting();
app.UseEndpoints(e => { e.MapControllers(); });
}
}
[TestMethod]
public async Task ReproduceIssueWhenDirectConsoleWriting()
{
// This use Console.Out.WriteLine that doesn't show the log from within controller.
var logger = new Logger();
await TryToReproduceIssueWithGivenLoggerAsync(logger);
}
[TestMethod]
public async Task ReproduceIssueWhenLoggingThroughAction()
{
// Attempt to use func to run in console configured outside app but didn't help any.
var logger = new Logger { LogAction = m => Console.WriteLine(m) };
await TryToReproduceIssueWithGivenLoggerAsync(logger);
}
[TestMethod]
public async Task WorksOnTediousContextChange()
{
// But if we just grab the state and log in a task/thread outside app context it works.
var myLog = new Queue<string>();
var logSent = new SemaphoreSlim(0);
var logWritten = new SemaphoreSlim(0);
var logWriterToken = new CancellationTokenSource();
var logWriter = Task.Run(async () =>
{
while (!logWriterToken.IsCancellationRequested)
{
try
{
await logSent.WaitAsync(logWriterToken.Token);
}
catch (OperationCanceledException)
{
break;
}
Console.WriteLine(myLog.Dequeue());
logWritten.Release();
}
});
var logger = new Logger
{
LogAction = m =>
{
myLog.Enqueue(m);
logSent.Release();
logWritten.Wait();
}
};
await TryToReproduceIssueWithGivenLoggerAsync(logger);
logWriterToken.Cancel();
await logWriter;
}
private async Task TryToReproduceIssueWithGivenLoggerAsync(Logger logger)
{
logger.Log("Starting");
using var webHost = WebHost.CreateDefaultBuilder()
.ConfigureServices(s =>
{
s.AddSingleton(this);
s.AddSingleton(logger);
}).UseStartup<Startup>()
.Build();
var ctoken = new CancellationTokenSource();
await webHost.StartAsync(ctoken.Token);
var addr = webHost.ServerFeatures.Get<IServerAddressesFeature>()?.Addresses.First();
var port = int.Parse(addr.Substring(addr.LastIndexOf(':') + 1));
Assert.IsTrue(port >= 1024 && port <= 65536);
using (var httpClient = new HttpClient())
{
var response = await httpClient.SendAsync(new HttpRequestMessage(HttpMethod.Get, new Uri($"http://localhost:{port}/api/test")));
Assert.AreEqual(HttpStatusCode.OK, response.StatusCode);
var content = await response.Content.ReadAsStringAsync();
Assert.AreEqual("Yay", content);
}
ctoken.Cancel();
await webHost.StopAsync(CancellationToken.None);
logger.Log("Done");
Assert.AreEqual("Starting, Test was called, Done", string.Join(", ", logger.RecordedLog));
}
}
}
I believe the reason the console output is not shown is because the ASP.NET server is running in a different
ExecutionContext.This answer to a similar question utilises the Microsoft.AspNetCore.TestHost.TestServer class. By setting the PreserveExecutionContext property to
true, this ensures the client and server are using the same execution context, and therefore console output becomes visible in the test logs.