Proper logging in .NET Core 3.0
In this post, I explain a minor upgrade in the ASP.NET Core logs messages on startup in ASP.NET Core 3.0. Instead of logging messages precisely to the console, ASP.NET Core now uses the logging infrastructure properly, producing structured records.
Proper logging in .NET Core 3.0
If we begin to use an ASP.NET Core 3.0 application using .net run, we'll recognize a subtle change in the log messages shown in the output window:
info: Microsoft.Hosting.Lifetime[0]
Now listening on: https://localhost:5001
info: Microsoft.Hosting.Lifetime[0]
Now listening on: http://localhost:5000
info: Microsoft.Hosting.Lifetime[0]
Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
data root path: C:\repos\andrewlock\blog-examples\suppress-console-messages
The startup messages are now coded using structured logging! But the change isn't as easy as using Logger rather than Console. It was the WebHost that was In ASP.NET Core 2.x was accountable for logging these messages. In ASP.NET Core 3.0, this information is logged by the ConsoleLifetime - the native IHostLifetime registered by the generic host.
In summary, this class is accountable for listening for the Ctrl+C keypress in the console and beginning the shutdown procedure.
The ConsoleLifetime also registers callbacks while its WaitForStartAsync() method, which is called when the ApplicationLifetime.ApplicationStarted event is generated, and also when the ApplicationLifetime.ApplicationStopping event is triggered:
public Task WaitForStartAsync(CancellationToken cancellationToken)
{
if (!Options.SuppressStatusMessages)
{
// Register the callbacks for ApplicationStarted
_applicationStartedRegistration = ApplicationLifetime.ApplicationStarted.Register(state =>
{
((ConsoleLifetime)state).OnApplicationStarted();
},
this);
// Register the callbacks for ApplicationStopping
_applicationStoppingRegistration = ApplicationLifetime.ApplicationStopping.Register(state =>
{
((ConsoleLifetime)state).OnApplicationStopping();
},
this);
}
// ...
return Task.CompletedTask;
}
These callbacks debug the OnApplicationStarted() and OnApplicationStopping() methods (shown below) which easly write to the logging infrastructure:
private void OnApplicationStarted()
{
Logger.LogInformation("Application started. Press Ctrl+C to shut down.");
Logger.LogInformation("Hosting environment: {envName}", Environment.EnvironmentName);
Logger.LogInformation("Content root path: {contentRoot}", Environment.ContentRootPath);
}
private void OnApplicationStopping()
{
Logger.LogInformation("Application is shutting down...");
}
The WindowsServiceLifetime and SystemdLifetime implementations use the same method to write log files using the standard logging infrastructure. However, the exact messages differentiate slightly.
Suppressing the startup messages with the ConsoleLifetime
One little surprising difference caused by the startup messages been built by the ConsoleLifetime is that you can no longer carry the messages.
Setting ASPNETCORE_SUPPRESSSTATUSMESSAGES does not affect - the messages will continue to be logged whether the environment variable is set or not!
As I've already pointed out, this isn't a big issue now, seeing as the messages are correctly logged using the Microsoft.Extensions.Logging infrastructure. But if these messages offend you due to some reason, and you dont want them, then you can set up the ConsoleLifetimeOptions in Startup.cs:
public class Startup
{
public void ConfigureServices(IServiceCollection services)
{
// ... other configuration
services.Configure<ConsoleLifetimeOptions>(opts => opts.SuppressStatusMessages = true);
}
}
You could even setup the SuppressStatusMessages field based on the availibility of the ASPNETCORE_SUPPRESSSTATUSMESSAGES environment variable if you want:
public class Startup
{
public IConfiguration Configuration { get; }
public Startup(IConfiguration configuration) => Configuration = configuration;
public void ConfigureServices(IServiceCollection services)
{
// ... other configuration
services.Configure<ConsoleLifetimeOptions>(opts
=> opts.SuppressStatusMessages = Configuration["SuppressStatusMessages"] != null);
}
}
If you do select to suppress the messages, note that Kestrel will still log the URLs it's listening on; there's no way to suppress those:
info: Microsoft.Hosting.Lifetime[0]
Now showing on: http://0.0.0.0:5000
info: Microsoft.Hosting.Lifetime[0]
Now listening on https://0.0.0.0:5001.
Add comment