I have previously posted about Implementing logging in .net core applications for logging, telemetry and your own sanity where I introduced the concepts of introducing Attributes and Middleware components in order to start developing an effective logging strategy for your application.
An effective logging strategy in your application is vital and you and your team will thank you in the weeks, months and years your application is running and when they need to find the root cause of bugs and issues.
We're going to dive in a little deeper into setting up our logging strategy and start to introduce our logging component. In the previous example, we simply logged the details to console, which may have suited our simple example, but it is in no way an effective implementation, and ideally we want to start setting up an effective logging solution for our software projects..
Ironically, we find that at most companies, Logging is often implemented as a mechanism to help them identify components of their architecture that are most frequently used etc. as one of the 8 best practices to reduce technical debt and how to measure technical debt. However, what I have found is that there implementation for logging actually introduces more technical debt!
ASP.NET Core includes some basic logging providers, but to get the most out of it you'll need to plug in a full logging framework like Serilog - simple .NET logging with fully-structured events.
What should we Log?
The question often asked when it comes to logging, What should we log? The short answer is Everything, however there is some nuance. We have to log everything that makes sense, because the long and the short of it is that deriving as much data as possible about the usage of our application provides business value in a myriad of ways.
In chapter 54 Inspired: How to create tech products customers love Marty Cagan emphasises the importance of good logging and analytics in applications during Quantitative Value Testing Techniques, and how product teams rely on this information to inform product designs and enhancements.
Inspired
How to Create Tech Products Customers Love
How do today's most successful tech companies-Amazon, Google, Facebook, Netflix, Tesla-design, develop, and deploy the products that have earned the love of literally billions of people around the world?
The typical aspects product teams look at and hope to identify when analyzing logs is:
- Major branching points in code
- Errors and unexpected values encountered
- IO or resource intensive operations
- Domain Events
- Request Failures
- Time consuming batch operations
Appropriate logging levels
Another popular question asked what are the appropriate logging levels to set. My typical answer is:
Be generous with your logging but be strict with your logging levels
In my opinion the level of your logs should always be Debug. Use Information for log events that are needed in production to help determine running state and stability of the application. Warning or Error for unexpected events.
What is Serilog
Serilog is a popular third party logging framework for .net, which was primarily developed with aim of implementing structured logging. The primary goal behind the concept of structured logging is to provide a more defined format and details to your logging.
Serilog plugs into ASP.NET Core and uses .NET Core standard API for logging, supporting ASP.NET Cores default logging APIs enables receiving log events from ASP.NET Core framework libraries.
What is structured logging
Log files generally are a form of unstructured text data, and even though can be really helpful can also be extremely difficult to discern practical information from. The goal of structured logging is to provide a solution to these sorts of problems and enable log files and data to used to provide additional data analytics about your application.
To enable log files to be machine readable they need to be in a structured format that can be easily parsed. This could be XML, JSON, or other formats. JSON is rapidly becoming the industry defacto standard these days and therefore you are most likely to see JSON as the standard format for structured logging.
Use cases for structured logging:
- Process log files for analytics or business intelligence – Processing web server access logs and basic summation and aggregates across the data.
- Searching log files – Search and correlate log messages for troubleshooting production problems.
Standard Log Properties
| Property Name | Description |
|---|---|
| ApplicationName | Name of the Application |
| ClientIP | IP Address of the client the request originated from |
| CorrelationId | ID that can be used to trace request across multiple application boundaries |
| Elapsed | TIme in milliseconds an operation takes |
| EventType | Hash of the message template to determine the message type |
| MachineName | Name of the machine which application is running |
| Outcome | The result of the operation |
| RequestMethod | HTTP request method name |
| RequestPath | Http request path |
| SourceContext | Name of component/class which the log originated |
| StatusCode | Http status code |
| UserAgent | Http User Agent |
| Version | Version of the application |
Serilog with .net core
.net core comes prepackaged with a reasonable set of defaults for diagnostic logging and as frameworks should it provides good API's for structured logging and and log events. What is also great about the .net framework in general, is that it also gets out of your way if you choose to implement something else or enhance what is already there.
Serilog is independent of .NET Core and most of the framework infrastructure, including configuration and dependency injection, making it well-suited to collecting and recording problems with starting up the framework itself, which is a critical role for a logging library.
For the purpose of this article we are going to add logging to the ever expanding demo application I'm building for my blog articles.
In order to implement SeriLog in a web application we can simply add the Serilog.Aspnetcore nuget package to our application
dotnet add package Serilog.AspNetCore
Once we have it installed lets go ahead and start implement in our application.
One of the first places you should actually implement logging in any application is the actual start up. Application can fail to start for any manner of reason, and having sufficient logging in place to capture some information as to why your application is failing to start and help overcome the issues caused.
In the Program.cs file of our application, we'll go ahead and configure our logger. We will slightly refactor the Main method to include the configuration of our logger and at the same time wrap our start up code up with some logging
public class Program
{
public static void Main(string[] args)
{
Log.Logger = new LoggerConfiguration()
.MinimumLevel.Override("Microsoft", LogEventLevel.Information)
.Enrich.FromLogContext()
.WriteTo.Console()
.CreateBootstrapLogger();
try
{
Log.Information("Blog Tutorials Application is starting");
CreateHostBuilder(args).Build().Run();
}
catch (Exception ex)
{
Log.Fatal(ex, "Blog tutorials application failed to start");
}
finally
{
Log.CloseAndFlush();
}
}
public static IHostBuilder CreateHostBuilder(string[] args) =>
Host.CreateDefaultBuilder(args)
.UseSerilog()
.ConfigureWebHostDefaults(webBuilder => { webBuilder.UseStartup<Startup>(); });
}
As you can tell, the configuration of the logger is relatively straight forward, and is made simpler by the fluent configuration style. We've added Enrich.FromLogContext() to the logger configuration, an enrichment that Serilog provides, which provides the capability to add and remove properties from the execution context, this feature needs adding to the logger at configuration time.
If we start and run our application we and inspect the terminal console we will see our log messages
This works great! However, what we really want to do is actually implement the logging in our Middleware component, which we discussed in Implementing logging in .net core applications for logging, telemetry and your own sanity. Also the logging here might help to catch general exceptions etc, but what we really want know when we're trouble shooting issues is the stack trace, and sometimes values from other configuration options can affect the start up of our application.
What we have implemented here, is only the first stage of what Serilog refers to as Two-Stage Initialisation. This has the benefit of catching and reporting exceptions thrown during set up of the ASP.NET core host.
The downside of iniitialising Serilog first is that services from the ASP.net core host, including appsettings.json configuration and dependency are not available at this stage of the pipeline.
To address this Serilog providers the Bootstrap logger which is configured immediately when the program starts then is replaced by the fully configured logger once the host is loaded. We'll learn how to configure the second stage of or initialisation shortly.
What you'll notice from this approach as compared to the approach in the previous article is just how much the output of the logging information has changed. We seem to have obtained some coloration in the output and it has been condensed a little more.
Serilog Configuration
This is in my opinion where Serilog really shines, it is relatively simple to configure Serilog and for the most part, you can do so by making use of the Application Settings configuration file. Alternatively if Fluent Configuration floats your boat, you can take this approach too.
The preference we usually make, is to provide the configuration via the Application Settings, because this provides us the great flexibility and enables us to modify the Serilog configuration without necessarily making code changes.
I will illustrate the Application Configuration approach in this post, and possibly in the future in another post illustrate how to do it via the Fluent Configuration approach.
In this step we will update our Program.cs to remove our configuration from the Main method, because in reality we don't necessarily want or need to configure our logger there, because a better place to do would be in the CreateHostBuilder method We will leave the UseSerilog() when we build the Host.
We'll make use of the lambda available which provides Serlog access to the HostBuilder context and LoggerConfiguration. We'll instruct Serilog to get its configuration options from the Host Context Configuration.
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Hosting;
using Serilog;
namespace Api
{
public class Program
{
public static void Main(string[] args)
{
CreateHostBuilder(args).Build().Run();
}
public static IHostBuilder CreateHostBuilder(string[] args) =>
Host.CreateDefaultBuilder(args)
.UseSerilog((hostContext, LoggerConfiguration) =>
{
LoggerConfiguration.ReadFrom.Configuration(hostContext.Configuration);
})
.ConfigureWebHostDefaults(webBuilder => { webBuilder.UseStartup<Startup>(); });
}
}
Due to the fact that we are going to configure our Logger using the configuration we need to go add that configuration. For the purpose of this guide, I will simply add this to the appsettings.json
{
"Serilog": {
"MinimumLevel": "Information",
"Override": {
"Microsoft.AspNetCore": "Warning"
},
"WriteTo": [
{
"Name": "Console",
"Args": {
"outputTemplate": "{Timestamp:HH:mm:ss.fff zzz} [{Level}] [{SourceContext}] {Message}{NewLine}{Exception}"
}
}
],
"Enrich": [
"FromLogContext",
"WithMachineName",
"WithProcessId",
"WithThreadId"
]
}
}
We can now go ahead and configure the logger in our start up file. The the only other bit of work we need to do here is ensure that we add a call to app.UseSerilogRequestLogging(); in the Configure method.
Serilog RequestLoggingMiddleware
The Request Logging Middleware is included in the Serilog.AspNetCore package and can be used to add a single summary log message for each request. When we add the UseSerilogRequestLogging() to the services collection, this in turn add the RequestLoggingMiddleWare the pipeline.
UseSerilogRequestLogging() condenses the important information about requests handled by ASP.NET Core in one clean, streamlined, request completion event.
The enables us to provide some overloads to the RequestLoggingOptions should we need them. The RequestLoggingOptions has several properties that enables customization of how the request logger generates log statements.
A simplified version of this class is below but I recommend reading the code of RequestLoggingOptions because it provides the additional commentary.
public class RequestLoggingOptions
{
public string MessageTemplate { get; set; }
public Func<HttpContext, double, Exception, LogEventLevel> GetLevel { get; set; }
public Action<IDiagnosticContext, HttpContext> EnrichDiagnosticContext { get; set; }
}
Overview of RequestLoggingOptions
- MessageTemplate controls how the log is rendered to a string
- GetLevel control whether a given log should be level
DebugInfoorWarning - EnrichDiagnosticContext Enables access properties of the Response, such as the status code, elapsed time, or the content type, this is where you could access Features that may be set by the middleware later in the pipeline
In later articles I will provide deeper explanations on how this all works but for now, lets just focus on to get Serilog configured and up and running in our very simple example. To enable Request logging we just have to add it the services collection in the Configure method
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.OpenApi.Models;
using Serilog;
namespace Api
{
public class Startup
{
public Startup(IConfiguration configuration)
{
Configuration = configuration;
}
public IConfiguration Configuration { get; }
// This method gets called by the runtime. Use this method to add services to the container.
public void ConfigureServices(IServiceCollection services)
{
services.AddControllers();
services.AddSwaggerGen(c =>
{
c.SwaggerDoc("v1", new OpenApiInfo {Title = "Api", Version = "v1"});
c.EnableAnnotations();
});
}
// This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
app.UseSerilogRequestLogging();
if (env.IsDevelopment())
{
app.UseDeveloperExceptionPage();
app.UseSwagger();
app.UseSwaggerUI(c => c.SwaggerEndpoint("/swagger/v1/swagger.json", "api v1"));
}
app.UseHttpsRedirection();
app.UseRouting();
app.UseAuthorization();
app.UseEndpoints(endpoints => { endpoints.MapControllers(); });
}
}
}
If we run our application now and hit our end points we'll see our data being presented. In the Console window
There are a few aspects of this log output worth taking note of
- HTTP method calls include all the relevant information you'll need i.e. Method, Path, Status Code and Duration
- Serilog starts timing requests when they reach its middleware and stop after generating the response.
- Structured Logging appends some additional values i.e. RequestId and SpanID
Conclusion
We've now implemented all that is required to get Serilog.AspnetCore request logging middleware to improve our logging infrastructure.
This is a great start to improving your logging, yet more can be achieved and in the forthcoming instalments of this series we will learn more about them.
- What is this Directory.Packages.props file all about? - January 25, 2024
- How to add Tailwind CSS to Blazor website - November 20, 2023
- How to deploy a Blazor site to Netlify - November 17, 2023