serilog-aspnetcore
serilog-aspnetcore copied to clipboard
serilog
.NET 6 WebApplicationFactory test throws System.InvalidOperationException : The entry point exited without ever building an IHost.
Description
When I have Serilog configured on my Program.cs and if I run more than one test that uses WebApplicationFactory I get an exception thrown System.InvalidOperationException : The entry point exited without ever building an IHost. accessing the application factory services.
Reproduction
Program.cs
using System.Text.Json.Serialization;
using Serilog;
Log.Logger = new LoggerConfiguration()
.WriteTo.Console()
.CreateBootstrapLogger();
Log.Information("Starting up...");
try
{
var builder = WebApplication.CreateBuilder(args);
builder.Host.UseSerilog((ctx, lc) => lc.ReadFrom.Configuration(ctx.Configuration));
var configuration = builder.Configuration;
var services = builder.Services;
// Add services to the container.
services.AddControllers()
.AddJsonOptions(options =>
{
options.JsonSerializerOptions.Converters.Add(new JsonStringEnumConverter());
})
.AddControllersAsServices();
services.AddEndpointsApiExplorer();
services.AddSwaggerGen();
var app = builder.Build();
app.UseSerilogRequestLogging();
app.UseCors(builder =>
builder
.WithOrigins(configuration.GetSection("AllowedOrigins")
.AsEnumerable()
.Select(kvp => kvp.Value)
.Where(origin => !string.IsNullOrEmpty(origin))
.ToArray()
)
.SetIsOriginAllowedToAllowWildcardSubdomains()
.AllowAnyMethod()
.AllowAnyHeader()
.AllowCredentials());
// Configure the HTTP request pipeline.
if (app.Environment.IsDevelopment())
{
app.UseSwagger();
app.UseSwaggerUI();
}
app.UseHttpsRedirection();
app.UseAuthentication();
app.UseAuthorization();
app.MapControllers();
app.Run();
return 0;
}
catch (Exception ex)
{
Log.Fatal(ex, "Host terminated unexpectedly.");
return 1;
}
finally
{
Log.CloseAndFlush();
}
#pragma warning disable CA1050 // Declare types in namespaces
public partial class Program { } // so you can reference it in tests
#pragma warning restore CA1050 // Declare types in namespaces
appsettings.json:
{
"AllowedHosts": "*",
"Serilog": {
"AllowedHosts": "*",
"MinimumLevel": {
"Default": "Information",
"Override": {
"Microsoft": "Warning",
"Microsoft.Hosting.Lifetime": "Information"
}
},
"Enrich": [
"FromLogContext"
],
"Filter": [
{
"Name": "ByExcluding",
"Args": {
"expression": "@mt = 'An unhandled exception has occurred while executing the request.'"
}
}
],
"WriteTo": [
{
"Name": "Console",
"Args": {
"outputTemplate": "[{Timestamp:HH:mm:ss} [{Level}]: {Message:l}{NewLine}{Exception}"
}
}
]
}
}
TestApplication.cs:
using Microsoft.AspNetCore.Mvc.Testing;
using Microsoft.Extensions.Hosting;
namespace Api.Tests;
internal class TestApplication : WebApplicationFactory<Program>
{
private readonly string environment;
public TestApplication(string environment = "Development")
{
this.environment = environment;
}
protected override IHost CreateHost(IHostBuilder builder)
{
builder.UseEnvironment(environment);
return base.CreateHost(builder);
}
}
SwaggerTest.cs:
using System.Linq;
using System.Threading.Tasks;
using FluentAssertions;
using Microsoft.Extensions.DependencyInjection;
using Swashbuckle.AspNetCore.Swagger;
using Xunit;
namespace Api.Tests.Swagger;
public class SwaggerTest
{
[Fact]
public async Task OperationIds_Should_Be_Unique()
{
await using var application = new TestApplication();
var swaggerProvider = application.Services.GetRequiredService<ISwaggerProvider>();
var swagger = swaggerProvider.GetSwagger("v1");
var operationIds = swagger.Paths.Values.SelectMany(path => path.Operations.Values.Select(operation => operation.OperationId)).ToList();
operationIds.Should().OnlyHaveUniqueItems();
}
[Fact]
public async Task OperationIds_Should_Be_Unique2()
{
await using var application = new TestApplication();
var swaggerProvider = application.Services.GetRequiredService<ISwaggerProvider>();
var swagger = swaggerProvider.GetSwagger("v1");
var operationIds = swagger.Paths.Values.SelectMany(path => path.Operations.Values.Select(operation => operation.OperationId)).ToList();
operationIds.Should().OnlyHaveUniqueItems();
}
}
Expected behavior Tests pass, and does not throw calling application.Services
Relevant package, tooling and runtime versions
<PackageReference Include="Serilog.AspNetCore" Version="4.1.0" />
<PackageReference Include="Serilog.Expressions" Version="3.2.1" />
dotnet --version:
6.0.102
Additional context
The tests pass if I comment out the line builder.Host.UseSerilog((ctx, lc) => lc.ReadFrom.Configuration(ctx.Configuration)); from Program.cs.
Thanks for the report! Someone will need to set up "break on all exceptions", or step through the test in a debugger to narrow it down. I assembled a test project using the sample above, without Swashbuckle and my test can instantiate the test host and resolve ILogger<Anything> successfully.
(Another approach might be to try dropping the Swashbuckle-related config from Program.cs and see whether you still hit an issue.)
Stack trace looks like this:
System.InvalidOperationException : The entry point exited without ever building an IHost.
Stack trace:
at Microsoft.Extensions.Hosting.HostFactoryResolver.HostingListener.CreateHost()
at Microsoft.Extensions.Hosting.HostFactoryResolver.<>c__DisplayClass10_0.<ResolveHostFactory>b__0(String[] args)
at Microsoft.AspNetCore.Mvc.Testing.DeferredHostBuilder.Build()
at Microsoft.AspNetCore.Mvc.Testing.WebApplicationFactory`1.CreateHost(IHostBuilder builder)
at Microsoft.AspNetCore.Mvc.Testing.WebApplicationFactory`1.DelegatedWebApplicationFactory.CreateHost(IHostBuilder builder)
at Microsoft.AspNetCore.Mvc.Testing.WebApplicationFactory`1.ConfigureHostBuilder(IHostBuilder hostBuilder)
at Microsoft.AspNetCore.Mvc.Testing.WebApplicationFactory`1.EnsureServer()
at Microsoft.AspNetCore.Mvc.Testing.WebApplicationFactory`1.CreateDefaultClient(DelegatingHandler[] handlers)
at Microsoft.AspNetCore.Mvc.Testing.WebApplicationFactory`1.CreateDefaultClient(Uri baseAddress, DelegatingHandler[] handlers)
at Microsoft.AspNetCore.Mvc.Testing.WebApplicationFactory`1.CreateClient(WebApplicationFactoryClientOptions options)
at Microsoft.AspNetCore.Mvc.Testing.WebApplicationFactory`1.CreateClient()
Probably I know why tests pass in debug or in coverage because than they are executed by IDE one after another, but problem only happens when tests are run parallel.
I can confirm that the problem happens only when tests are run in parallel. When I run test with the config:
{
"$schema": "https://xunit.net/schema/current/xunit.runner.schema.json",
"parallelizeTestCollections": false
}
they all pass, but unfortunately it's not a solution at my case. I strongly need run tests parallelly.
Does the issue persist if you switch from CreateBootstrapLogger() to CreateLogger()?
Changing Serilog initialization in Program.cs from:
Log.Logger = new LoggerConfiguration()
.WriteTo.Console()
.CreateBootstrapLogger();
to:
Log.Logger = new LoggerConfiguration()
.WriteTo.Console()
.CreateLogger();
solved the problem. @nblumhardt could you explain why is that?
@pikoscielniak thanks for helping to track it down. CreateBootstrapLogger() creates a ReloadableLogger, which the UseSerilog() callback reconfigures and then freezes.
Freezing is a stateful operation:
https://github.com/serilog/serilog-extensions-hosting/blob/dev/src/Serilog.Extensions.Hosting/Extensions/Hosting/ReloadableLogger.cs#L80
Not sure how best to avoid this in testing.. 🤔
@nblumhardt does using CreateLogger instead of CreateBootstrapLogger have any dangerous influence on running on production?
https://nblumhardt.com/2020/10/bootstrap-logger/#why-cant-we-just-do-both has some info on the problems CreateBootstrapLogger() resolves; if those issues don't apply to you then it's fine to just use CreateLogger() instead.
Just adding another voice here that we're also seeing this exception in parallel unit tests when using WebApplicationFactory and CreateBootstrapLogger().
Not sure if this is the right place to make a comment, but I think I've just hit this condition - but not when unit testing.
At least in my case, I am adding a ILogEventSink to the service collection using a factory method:
// Custom Serilog Sinks
services.AddSingleton<ILogEventSink>(provider =>
{
...
});
However, when I use the provider to resolve a service, there seems to be a reentry going on somewhere as it cycles back to the builder.Host.UseSerilog((context, serviceProvider, configuration) method, and continues to loop forever.
I'm unsure if it's a Serilog issue or a NET6 / AspNetCore issue.
Workaround with logger set did not work for me.
Log.Logger = new LoggerConfiguration()
.WriteTo.Console()
.CreateLogger();
I'm also having the same issue when tests are run in parallel. I'm using a wrapper library to create the logger, which internally calls the CreateLogger(), not CreateBootstrapLogger(). Anyone have a workaround? I can't change which Serilog method is called to create the logger. (Though it seems I'm already using the method that should be better, for this issue.)
I'd obviously rather not have to force the tests to all run synchronously.
@span @MichaelDeutschCoding sounds like you're hitting something else; if you're sure it's Serilog-related, could you please post a new issue and include as much detail as possible? Thanks!
@span @MichaelDeutschCoding sounds like you're hitting something else; if you're sure it's Serilog-related, could you please post a new issue and include as much detail as possible? Thanks!
I can confirm my issues were not only Serilog related and they are now resolved. I had two issues. I did feel the need to post here though, since Google search result were sparse on the error message.
-
The same as mentioned, where the bootstrap logger was causing the problem and the suggested fix works fine. I do get another error message when using the bootstrap logger though.
System.InvalidOperationException: The logger is already frozen.. -
I also had to remove a try/catch statement that I had around my app code in
Program.cs. I was using the try/catch for some debugging but it seems it actually caused this sameIHosterror. Not sure if it is a bug or feature, but it is .net core related rather than serilog.
@span @MichaelDeutschCoding sounds like you're hitting something else; if you're sure it's Serilog-related, could you please post a new issue and include as much detail as possible? Thanks!
I can confirm my issues were not only Serilog related and they are now resolved. I had two issues. I did feel the need to post here though, since Google search result were sparse on the error message.
1. The same as mentioned, where the bootstrap logger was causing the problem and the suggested fix works fine. I do get another error message when using the bootstrap logger though. `System.InvalidOperationException: The logger is already frozen.`. 2. I also had to remove a try/catch statement that I had around my app code in `Program.cs`. I was using the try/catch for some debugging but it seems it actually caused this same `IHost` error. Not sure if it is a bug or feature, but it is .net core related rather than serilog.
A switch from CreateBootstrapLogger() to CreateLogger() worked out for me. I still have the try/catch block around everything in Program.cs
Same issue here.
This is an ugly issue IMO because if you try and do everything right by following the Serilog docs and use CreateBootstrapLogger() and you follow the official Microsoft Integration Testing Docs which recommend creating test classes with ITestFixture<CustomWebAppFactory<Program>> by default everything will run in parallel and you will hit this bug and then spend maybe hours fighting it before you land here on this issue from Google.
Maybe the Serilog docs could be improved to warn of this? IE:
If you use
CreateBootstrapLogger()along with XUnit parallel tests, an exception may get thrown in your startup/program as the freezing of the ReloadableLogger is a stateful operation.
Or maybe there is a way for someone much smarter than me to maker a change in CreateBootstrapLogger() to circumvent this issue?
I ran into this today and settled on the following workaround.
Step 1 : inject a setting during the test server bootstrap
public class CustomWebAppFactory
: WebApplicationFactory<Your.Program>
{
protected override void ConfigureWebHost(IWebHostBuilder builder)
{
builder.UseSetting("integrationTest", "true");
...
}
Step 2: pull out the arg and conditionally build your loggers
public static Serilog.ILogger CreateIntegrationTestLogger()
=> new LoggerConfiguration()
.WriteTo.Console()
.CreateLogger();
public static Serilog.ILogger CreateBootstrapLogger()
=> new LoggerConfiguration()
.WriteTo.Console()
.CreateBootstrapLogger();
public static void Main(string[] args)
{
var isIntegrationTest = args.Contains("--integrationTest=true");
Log.Logger = isIntegrationTest ? CreateIntegrationTestLogger() : CreateBootstrapLogger();
...
}
Another option would be to use Debug/Release pragma to define the logger behaviour or the --environment="Development" flag which is also available in the args array. That choice depends on what env + build config you choose to run your tests.
Is it too dirty? The problem is that the host creation is called multiple time during test. I am not sure If it will influence in production.
Log.Logger = new LoggerConfiguration()
.Enrich.FromLogContext() ...
.CreateBootstrapLogger();
bool preserveStaticLogger = Program.UseSerilogAlreadyCalled;
Program.UseSerilogAlreadyCalled = true;
builder.Host.UseSerilog((context, services, configuration) =>
configuration
.ReadFrom.Configuration(context.Configuration) ... ,
preserveStaticLogger: preserveStaticLogger
);
public partial class Program {
public static bool UseSerilogAlreadyCalled = false;
}
Are we obligated to use Log.Logger?
I've solved this problem like that:
using Serilog;
using var log = new LoggerConfiguration()
.WriteTo.Console()
.CreateLogger();
try
{
var builder = WebApplication.CreateBuilder(args);
builder.Host.UseSerilog((ctx, sp, conf) => conf.ReadFrom.Configuration(ctx.Configuration)));
// builder configuration omitted
var app = builder.Build();
// app configuration omitted
app.Run();
}
catch (Exception ex)
{
log.Fatal(ex, "An unhandled exception occurred during bootstrapping");
}
public partial class Program { }
@nblumhardt Coming in as another mildly annoyed person who followed both Serilog and MSFT's documentation for appropriately using Serilog and E2E testing w/ WebApplicationFactory, and after a couple days of trial and error, stumbled across parallelization as the culprit and thus this issue. It would be great to either see a resolution or perhaps an edit to the documentation for CreateBootstrapLogger that it can cause issues in these scenarios.
If following the approach suggested by gritcsenko above, is there a way to do the equivalent of Log.CloseAndFlush();?
Another workaround: Derive from WebApplicationFactory<TEntryPoint> if you aren't already, and add the following:
private static readonly object _lock = new();
/// <summary>
/// There is a problem with using Serilog's "CreateBootstrapLogger" when trying to initialize a web host.
/// This is because in tests, multiple hosts are created in parallel, and Serilog's static logger is not thread-safe.
/// The way around this without touching the host code is to lock the creation of the host to a single thread at a time.
/// </summary>
/// <param name="builder"></param>
/// <returns></returns>
protected override IHost CreateHost(IHostBuilder builder)
{
lock (_lock)
return base.CreateHost(builder);
}
This will make sure the host will be initialized in a single thread. Short of yanking out the BootstrapLogger, that's the only minimally-invasive approach I've found.
