Writing code and building software systems is a complex and challenging process. The more tools we have to streamline this process, the better the result. One underestimated aspect of software development that helps towards this goal is logging.
What is logging?
Logging is the process of tracking events and activities in a system or an application. It helps us detect security vulnerabilities, trace requests, analyze user activities, and debug our apps.
Why Choose Serilog?
Serilog is one of the most popular .NET logging libraries. It provides many features and simplifies developers’ lives when logging is implemented. It comes with built-in structured logging, one of our main goals when logging events. It creates a logging environment that makes searching and analyzing logs easier.
Getting Started with Serilog
Before we dive in, install the required package using the CLI:
| 1 | dotnet add package Serilog.AspNetCore
|
This package provides enhanced integration with ASP.NET Core. We chose this package over the base Serilog library to leverage its deep framework integration.
Next, we need to configure Serilog into our application, and we will leverage the configuration system provided by .NET. The benefit of this approach is that we don’t have to deploy our application for every change; we just need to update the appsettings.json.
Below is the configuration:
| 12345678910111213141516171819202122232425262728293031323334 | {
"Serilog": {
"Using": [ "Serilog.Sinks.Console", "Serilog.Sinks.File" ],
"MinimumLevel": {
"Default": "Information",
"Override": {
"Microsoft": "Warning",
"System": "Warning"
}
},
"WriteTo": [
{
"Name": "Console",
"Args": {
"outputTemplate": "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj} {Properties}{NewLine}{Exception}"
}
},
{
"Name": "File",
"Args": {
"path": "Logs/log-.txt",
"rollingInterval": "Month",
"rollOnFileSizeLimit": true,
"outputTemplate": "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj} {Properties}{NewLine}{Exception}"
}
}
],
"Enrich": [ "FromLogContext", "WithMachineName", "WithThreadId", "WithProcessId" ],
"Properties": {
"Application": "ECommerceWebsite"
}
},
"AllowedHosts": "*"
}
|
Let’s break down each section of the configuration file to understand its purpose and how it impacts logging behavior:
Using:
In the using section, we have 2 packages, Serilog.Sinks.Console, Serilog.Sinks.File. With this configuration, we can dynamically resolve the needed libraries. The first allows you to print logs directly to the console, and the second enables logs to be written to a file on disk.
MinimumLevel:
Specifies the default log level, which is information in our case, and overrides the Microsoft default logging.
WriteTo:
In this section, we specify where the log data should be written. We added two options: in the console and a file. For the output to be consistent, the same Args configuration is applied to both. In the file section, we also included the timeframe that the log file will be preserved and the rollOnFileSizeLimit, which enables rolling over files when they reach the maximum file size limit (the default is 1 GB).
Enrich:
With this section, we can enrich our logs with extra information. In our application, we have selected the following enrichers:
FromLogContext: Captures context-specific properties added during logging.
WithMachineName: Includes the machine name where the log was generated.
WithThreadId: Logs the thread ID for troubleshooting concurrency issues.
WithProcessId: It helps debug issues tied to specific processes.
For the enrichers to be displayed, we also need these NuGet packages:
| 123 | dotnet add package Serilog.Enrichers.Environment
dotnet add package Serilog.Enrichers.Thread
dotnet add package Serilog.Enrichers.Process
|
Serilog.Enrichers.Environment ->Adds the machine name (MachineName)
Serilog.Enrichers.Thread -> Adds the thread ID (ThreadId)
Serilog.Enrichers.Process -> Adds the process ID (ProcessId)
Properties:
The Properties section allows you to define static fields that will be included in every log entry. We added the following property: Application: ECommerceWebsite
Next, we will configure Serilog in the program.cs file, with the option to read the configuration from the appsettings.json file:
| 12 | builder.Host.UseSerilog((context, configuration) =>
configuration.ReadFrom.Configuration(context.Configuration));
|
This step ensures that Serilog’s settings, such as sinks, log levels, and enrichers, are applied from the configuration file. We can test it with this logging statement:
| 1 | Log.Information("The application has started successfully.");
|
And the log entry that generates:
| 1 | 2024-11-30 09:35:37.261 +02:00 [INF] The application has started successfully. { MachineName: "DESKTOP-C2SMT2J", ThreadId: 1, ProcessId: 21344, Application: "ECommerceWebsite" }
|
Another useful middleware that comes with Serilog is the one that enables automatic logging of incoming HTTP requests:
| 1 | app.UseSerilogRequestLogging();
|
This middleware creates an extra log with details about the HTTP request. Be sure to add it before any middleware that handles requests.
Tracking Product Actions with Structured Logging
Now that we have everything ready, let’s inject the logger into our controllers for tracking user activities, such as viewing products, adding items to the cart, and placing orders.
Let’s implement structured logging to track when a user views a product.
| 1234567891011121314151617181920212223 | using Microsoft.AspNetCore.Mvc;
[ApiController]
[Route("api/[controller]")]
public class ProductController : ControllerBase
{
private readonly Serilog.ILogger _logger;
public ProductController(Serilog.ILogger logger)
{
_logger = logger;
}
[HttpGet("{id}")]
public IActionResult GetProductDetails(int id)
{
var product = new { Id = id, Name = "Sample Product", Price = 50.00 };
_logger.Information(
"User {UserId} viewed product {ProductId} at {Timestamp}",
User?.Identity?.Name ?? "Guest",
id,
DateTime.UtcNow
);
return Ok(product);
}
}
|
The log method accepts a message template syntax to create structured and human-readable log messages, with placeholders and the corresponding values. The message template looks like this:
User {UserId} viewed product {ProductId} at {Timestamp}
UserId: Captures the currently logged-in user’s name or defaults to Guest if the user is not authenticated.
ProductId: Records the ID of the product being viewed.
Timestamp: Captures the exact time the action occurred, in UTC.
The generated log has this format:
| 1 | 2024-11-30 09:36:56.252 +02:00 [INF] User Guest viewed product 1 at "2024-11-30T07:36:56.2519069Z" { ActionId: "17febea6-9d7b-40d6-9de1-6badeda81761", ActionName: "ProductController.GetProductDetails (ecommerce-logging)", RequestId: "0HN8H27070MQI:0000000F", RequestPath: "/api/Product/1", ConnectionId: "0HN8H27070MQI", MachineName: "DESKTOP-C2SMT2J", ThreadId: 7, ProcessId: 11076, Application: "ECommerceWebsite" }
|
And the log generated from the HTTP request middleware, which we registered previously, is as follows:
| 1 | 2024-11-30 09:36:56.269 +02:00 [INF] HTTP GET /api/Product/1 responded 200 in 37.9847 ms { SourceContext: "Serilog.AspNetCore.RequestLoggingMiddleware", RequestId: "0HN8H27070MQI:0000000F", ConnectionId: "0HN8H27070MQI", MachineName: "DESKTOP-C2SMT2J", ThreadId: 7, ProcessId: 11076, Application: "ECommerceWebsite" }
|
We start seeing the benefits of structured logging, such as searchability with user and product IDs, readability with a consistent structure, and valuable metadata to enhance the overall observability of the application.
Tracking Cart Actions with Structured Logging
Logging cart actions is important for understanding user behavior, such as adding items to the cart, removing them, or updating quantities. Let’s extend our e-commerce application with a CartController by adding structured logging to capture information about the item being added.
| 1234567891011121314151617181920212223242526272829 | using Microsoft.AspNetCore.Mvc;
[ApiController]
[Route("api/[controller]")]
public class CartController : ControllerBase
{
private readonly Serilog.ILogger _logger;
public CartController(Serilog.ILogger logger)
{
_logger = logger;
}
[HttpPost("add")]
public IActionResult AddToCart([FromBody] CartItem item)
{
var result = new { Success = true, Item = item };
_logger.Information(
"User {UserId} added product {ProductId} with quantity {Quantity} to cart at {Timestamp}",
User?.Identity?.Name ?? "Guest",
item.ProductId,
item.Quantity,
DateTime.UtcNow);
return Ok(result);
}
public class CartItem
{
public int ProductId { get; set; }
public int Quantity { get; set; }
}
}
|
The process is similar with logger injection and using structured logs, as shown earlier, plus quantity as additional detail. As we proceed with the development of the application we maintain the same structure in our logs, something that will help us, as the application evolves.
With these logs about cart activity, we can easily find popular products and identify frequent user actions related to this. An example log entry is:
| 1 | 2024-11-30 09:38:19.908 +02:00 [INF] User Guest added product 1 with quantity 3 to cart at "2024-11-30T07:38:19.9087971Z" { ActionId: "27f5874f-0cf3-48ee-a0e9-31807cbafb78", ActionName: "CartController.AddToCart (ecommerce-logging)", RequestId: "0HN8H27NQ4HB8:0000000F", RequestPath: "/api/Cart/add", ConnectionId: "0HN8H27NQ4HB8", MachineName: "DESKTOP-C2SMT2J", ThreadId: 5, ProcessId: 15444, Application: "ECommerceWebsite" }
|
Adding Structured Logging for Order Checkout
Nothing matters more than checkout for a company to survive in the market. It is a critical e-commerce workflow to identify things such as successful transactions, troubleshoot failed orders, and analyze purchasing behavior.
Using the same approach as in our previous controllers, the OrderController is implemented as follows:
| 1234567891011121314151617181920212223242526272829303132333435363738394041424344 | using Microsoft.AspNetCore.Mvc;
[ApiController]
[Route("api/[controller]")]
public class OrderController : ControllerBase
{
private readonly Serilog.ILogger _logger;
public OrderController(Serilog.ILogger logger)
{
_logger = logger;
}
[HttpPost("create")]
public IActionResult CreateOrder([FromBody] Order order)
{
var result = new
{
Success = true,
OrderId = Guid.NewGuid(),
Order = order
};
foreach (var item in order.Items)
{
_logger.Information(
"User {UserId} created an order with ID {OrderId}, product {ProductId}, quantity {Quantity}, and total amount {TotalAmount} at {Timestamp}",
User?.Identity?.Name ?? "Guest",
result.OrderId,
item.ProductId,
item.Quantity,
order.TotalAmount,
DateTime.UtcNow);
}
return Ok(result);
}
public class Order
{
public List<OrderItem> Items { get; set; } = new List<OrderItem>();
public decimal TotalAmount { get; set; }
}
public class OrderItem
{
public int ProductId { get; set; }
public int Quantity { get; set; }
public decimal Price { get; set; }
}
}
|
With information like TotalAmount, you can enable real-time tracking of revenue. Correlating this data with specific orders allows you to uncover valuable purchase patterns.
Here’s a sample log generated during an order creation process:
| 1 | 2024-11-30 11:01:34.402 +02:00 [INF] User Guest created an order with ID "0e3d9d81-2023-4795-8cf8-0587723772f0", product 1, quantity 1, and total amount 10 at "2024-11-30T09:01:34.4027223Z" { ActionId: "08a320ee-3992-4275-9601-f548b7afd46e", ActionName: "OrderController.CreateOrder (ecommerce-logging)", RequestId: "0HN8H3M2C82KV:00000011", RequestPath: "/api/Order/create", ConnectionId: "0HN8H3M2C82KV", MachineName: "DESKTOP-C2SMT2J", ThreadId: 11, ProcessId: 27960, Application: "ECommerceWebsite" }
|
Conclusion
In this article, we saw how to implement structured logging using Serilog. The ultimate goal is to have the same log output in any case, so it will be easier to find what happened in our applications in the time we need. With features like sinks, enrichment, and structured templates, Serilog enables us to capture a complete picture of what happens in our applications.
