Achieving a high-traffic API is a common goal for numerous digital products, aiming to serve thousands of users. However, this success comes with its own set of challenges, particularly in debugging. Locating a specific issue within vast amounts of data can often feel like finding a needle in a haystack. In this blog post, I’ll present one solution to this problem using Serilog and ActionFilters in a .Net API. This will also serve as a good introduction to these technologies.
What is Serilog?
Serilog is a logging provider for.Net. I use it in all my projects and have advocated for its use in every project I have participated in. It is easy to use, configure, and extend with custom features. Serilog has a large and active community, offering many features that can be used out-of-the-box via NuGet packages.
These features generally fall into two categories: Sinks and Enrichers. Sinks are responsible for directing where logs are stored. They can route logs to various destinations, such as the console, files, or cloud services like Azure Application Insights. Enrichers enhance logs by automatically adding extra information. This means you don’t have to manually include this data every time you log an event, streamlining the logging process.
Getting Started with Serilog
To add Serilog to your project, start by creating a new ASP.NET Core Web API using .NET 8 and the default settings in Visual Studio.
After creating the project, install Serilog and Serilog.Sinks.Console via NuGet packages.
- Serilog is the main package used for logging
- Serilog.Sinks.Console is a sink that sends log messages to the console, which is sufficient for this blog.
To configure the logger, go to Program.cs and add the following code excerpt:
Log.Logger = new LoggerConfiguration()
.WriteTo.Console()
.CreateLogger();This code sets up Serilog, adds the console sink, and creates a static Log class that will be used for logging.
Note: Configurations can be read from appsettings.json, but this is enough for this example.
Implementing Logging in Your API
Now, we can log a message in our API. To log an executing endpoint message in the API, include the following line in the default endpoint:
[HttpGet(Name = "GetWeatherForecast")]
public IEnumerable<WeatherForecast> Get()
{
Log.Information("GetWeatherForecast executing...");
return Enumerable.Range(1, 5).Select(index => new WeatherForecast
{
Date = DateOnly.FromDateTime(DateTime.Now.AddDays(index)),
TemperatureC = Random.Shared.Next(-20, 55),
Summary = Summaries[Random.Shared.Next(Summaries.Length)]
})
.ToArray();
}Here, I use Log.Information since “Information” is the default log level for Serilog. If we execute this endpoint, we get the following log:
GetWeatherForecast executing...This is already useful, and other endpoints that will be added in the future will have their logs detailing their execution. However, there are cases where this may not be enough.
Advanced Logging Scenarios
What if an endpoint does not have any logs? What if its execution fails before anything is logged? Or what if it fails after the last log?
For these scenarios, out-of-the-box solutions exist, such as the UseSerilogRequestLogging() method available via the Serilog.AspNetCore NuGet package. However, these solutions offer limited control over logging, which may result in suboptimal logs or even lead to unexpected and harmful behavior. For example, if you enable the Azure Blob Storage Serilog sink, every message will be logged on Azure Blob Storage via a request. This can lead to a loop where a message is logged via a request, this request is then automatically logged via another request, and so on until your funds on Azure have been deleted.
For this use case, we want more control over when and how we log our requests, preferably separate from the request itself. To achieve this, we can use ActionFilters.
What are ActionFilters?
ActionFilters are an AspNetCore feature that is very underutilized. It enables you to run custom code before and after targeted endpoints are executed, with information available on the endpoint itself. It is sometimes used for custom authentication and authorization since you can check a user’s credentials and rights before an endpoint is triggered. You can use them for a particular endpoint or controller via an attribute, or globally, for all controllers.
Implementing a LogActionFilter
In this example, we will demonstrate logging the start and end of an action by creating a LogActionFilter class that implements the IActionFilter interface:
using Microsoft.AspNetCore.Mvc.Filters;
using Serilog;
namespace SerilogRequestLogging.API.Filters;
public class LogActionFilter : IActionFilter
{
public void OnActionExecuting(ActionExecutingContext context)
{
Log.Information("Action started.");
}
public void OnActionExecuted(ActionExecutedContext context)
{
Log.Information("Action executed.");
}
}
To use it for all endpoints across all controllers, we must modify the AddControllers method in Program.cs like this:
builder.Services.AddControllers(config => config.Filters.Add<LogActionFilter>());
If we start the API and execute the same endpoint again, the log will look like this:
[20:32:58 INF] Action started.
[20:32:58 INF] GetWeatherForecast executing...
[20:32:58 INF] Action executed.This is already incredibly useful, as we can see when the endpoint started and that it executed successfully, as far as the API is concerned. But we can get some extra information that can make this more useful.
Enhancing Endpoint Logging with Parameters
You can expand the default endpoint to accept parameters. This allows us to log not only the execution of the endpoint but also the input parameters. Thereby offering a more detailed view of each request.
[HttpGet(Name = "GetWeatherForecast")]
public IEnumerable<WeatherForecast> Get(string firstParam, string secondParam, string thirdParam)
{
Log.Information("GetWeatherForecast executing...");
return Enumerable.Range(1, 5).Select(index => new WeatherForecast
{
Date = DateOnly.FromDateTime(DateTime.Now.AddDays(index)),
TemperatureC = Random.Shared.Next(-20, 55),
Summary = Summaries[Random.Shared.Next(Summaries.Length)]
})
.ToArray();
}We can extract the parameter information, both the names of the parameters as well as the values, from the action filter. Furthermore, the name of the controller and the endpoint being executed can also be extracted. We can do this with the following code:
public void OnActionExecuting(ActionExecutingContext context)
{
var (ControllerName, ActionName) = GetActionInfo(context);
Log.Information($"Started {ControllerName}.{ActionName}");
}
private static (string ControllerName, string ActionName) GetActionInfo(FilterContext context)
{
var descriptor = (ControllerActionDescriptor)context.ActionDescriptor;
return (descriptor.ControllerName, descriptor.ActionName);
}The context we get from the implemented methods already contains all the information we need. We can create the GetActionInfo method just so the code that extracts this information is easier to read. We can add this information to our logs. Next, we can check if there are any parameters, called ActionArguments in the context, and log them as well:
public void OnActionExecuting(ActionExecutingContext context)
{
var (ControllerName, ActionName) = GetActionInfo(context);
Log.Information($"Started {ControllerName}.{ActionName} with parameters:");
if (context.ActionArguments.Any())
{
Log.Information(string.Join(", ", context.ActionArguments.Select(_ => $"{_.Key}: {_.Value}")));
}
} This results in the following log:
[20:37:46 INF] Started WeatherForecast.Get with parameters:
[20:37:46 INF] firstParam: valueOne, secondParam: valueTwo, thirdParam: valueThree
[20:37:46 INF] GetWeatherForecast executing...
[20:37:46 INF] Executed WeatherForecast.Get.These logs are already very useful and could be taken a step further if needed. For instance, values we get through parameters will not always be as primitive, but incoming objects can usually be serialized and logged. If not, we can omit certain classes from being logged, e.g. the CancellationToken class whose instances may throw an exception if we try to serialize them.
But what happens if we have a large number of users, all of them call the same endpoint at the same time, all the logs get mixed, and only one user experiences an error? How do we differentiate between requests?
That’s where the Trace Identifier comes in.
What is a Trace identifier?
Trace identifiers are unique identifiers representing requests. When numerous users frequently access the same endpoints, these identifiers enable us to match logs with their corresponding requests. This matching process is crucial for identifying bugs.
We can get the trace identifier from the context available in our action filter and include it in our logs there without a problem but this will only log it in the action filter. However, if we want to see the trace during the entire request, we’ll want to add the same trace identifier in our action filter, controller, services, etc. Thankfully, Serilog allows us to do just that via a log context enricher.
Configuring Serilog to Include Trace Identifiers
This is a default Serilog feature, so no additional NuGet packages are necessary. First, we need to modify Program.cs to include the following:
Log.Logger = new LoggerConfiguration()
.Enrich.FromLogContext()
.WriteTo.Console(outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {TraceIdentifier} {Message:lj}{NewLine}{Exception}")
.CreateLogger();The first line deals with enrichers. Enrichers give additional information to Serilog so it can add it to logs without us always having to explicitly tell it to do that. Also, we can add this information in one place in our code, which makes it easier to change and maintain. This line tells Serilog that we will be putting additional info to its log context, and to look for that information there.
In the second line, we modify the console sink so it uses a custom output template. This template is, in fact, almost identical to the default Serilog output template, but with {TraceIdentifier} added. This means that, if Serilog finds a value with the name “TraceIdentifier“, it will write it in this location.
Lastly, we need to insert the trace identifier in the log context. We get the trace identifier in the action filter, so we place it there before anything related to the requests has been logged:
public void OnActionExecuting(ActionExecutingContext context)
{
var (ControllerName, ActionName) = GetActionInfo(context);
LogContext.PushProperty("TraceIdentifier", $"[{context.HttpContext.TraceIdentifier}]");
Log.Information($"Started {ControllerName}.{ActionName} with parameters:");
if (context.ActionArguments.Any())
{
Log.Information(string.Join(", ", context.ActionArguments.Select(_ => $"{_.Key}: {_.Value}")));
}
}Apart from this line, no other logs need to be changed. Trace identifiers are unique to a single request, and log contexts are not shared between requests, so we know everything logged with the same trace identifier belongs to a single request. If we start the API now and call the endpoint twice, we get this log:
[20:43:52 INF] [0HN110A9A62L6:00000009] Started WeatherForecast.Get with parameters:
[20:43:52 INF] [0HN110A9A62L6:00000009] firstParam: valueOne, secondParam: valueTwo, thirdParam: valueThree
[20:43:52 INF] [0HN110A9A62L6:00000009] GetWeatherForecast executing...
[20:43:52 INF] [0HN110A9A62L6:00000009] Executed WeatherForecast.Get.
[20:43:59 INF] [0HN110A9A62L6:0000000B] Started WeatherForecast.Get with parameters:
[20:43:59 INF] [0HN110A9A62L6:0000000B] firstParam: valueOne, secondParam: valueTwo, thirdParam: valueThree
[20:43:59 INF] [0HN110A9A62L6:0000000B] GetWeatherForecast executing...
[20:43:59 INF] [0HN110A9A62L6:0000000B] Executed WeatherForecast.Get.Trace identifiers can look similar, but on closer inspection, they are unique to each request. In a mess of thousands upon thousands of intersecting requests, trace identifiers coupled with a good log reader can be a lifesaver.
Conclusion
This was only a small glimpse into what Serilog and action filters are capable of. Serilog is an extremely powerful tool, with many sinks and enrichers only a few clicks away, and with many powerful features available right out of the box. Action filters are incredibly useful as well, and extremely underutilized for the amount of utility they provide, limited only by our imagination.