In the last article, I wrote about logging in C# and how to use log formatters to suit your needs. Once you start adding logs to your applications, you start to notice there is too much info that you must add to every message: the event id, level, scopes, besides the message (which you can even add parameters, if you also want to do some structured logging).
When the project starts to grow, some issues with the logging appear: you cannot enforce standards and you may miss some messages (Did you add the correct event id to the message? Should it be a trace or an info message?) when processing the logs.
Fortunately, Microsoft introduced Compile-time logging source code generation. With this, you can customize your log messages and ease the task of adding logs.
The generated code will use the LoggerMessage.Define functionality to generate code at compile time that is much faster than run time approaches.
To use the source code generator, all you have to do is to have a partial class with a partial method, decorated with the LoggerMessage attribute. With that, the implementation for the partial method will be generated by the compiler.
In this article, we will take the project created in this article and add some code generated logging to it. This project can be downloaded at https://github.com/bsonnino/CustomerService.
Once we download and run it, we can open Swagger to test it with https://localhost:7191/swagger/index.html (the port number can change). In the console window, you will see something like this:
Now, we will start to customize our log messages. For that, we will create a new partial static class and will name it LogExtensions. In this class, we will add a partial method named ShowRetrievedCustomerCount and will decorate it with the LoggerMessage attribute:
public static partial class LoggerExtensions
{
[LoggerMessage(EventId = 100, Level = LogLevel.Information,
Message = "{methodName}({lineNumber}) - Retrieved {Count} customers")]
public static partial void ShowRetrievedCustomerCount(this ILogger logger,
int count, [CallerMemberName] string methodName = "", [CallerLineNumber] int lineNumber = 0);
}
And that's all we need for now. Some notes, here:
- I'm passing the
ILoggerinstance as a parameter for the function. That's needed for the source code generation work. It doesn't need to be the first parameter, but it must be present. - I used the keyword
thisfor theILoggerparameter. This is not mandatory, but I wanted to make this method as an extension method, so it can be called withlogger.ShowRetrievedCustomerCount(10) - The method must be void
- I am passing the method name and line number, obtained with the attributes
CallerMemberNameandCallerLineNumber
With that, we can use our new function for the logging:
app.MapGet("/customers", async (CustomerDbContext context) =>
{
var customers = await context.Customer.ToListAsync();
logger.ShowRetrievedCustomerCount(customers.Count);
return Results.Ok(customers);
});
When we run the code and test it, we get:
As you can see, the message is output to the console, with level Information and event id 100. It is a structured message (the customer count is a variable of the message) and it has the source method name and line.
We can change the format of the messages and remove the Entity Framework messages by changing the appsettings.json file to:
{
"Logging": {
"LogLevel": {
"Default": "Information",
"Microsoft.AspNetCore": "Warning",
"Microsoft.EntityFrameworkCore": "Warning"
},
"Console": {
"FormatterName": "simple",
"FormatterOptions": {
"SingleLine": true,
"IncludeScopes": false,
"TimestampFormat": "yyyy-MM-dd HH:mm:ss zzz ",
"ColorBehavior": "enabled",
"JsonWriterOptions": {
"Indented": true
}
}
}
},
"AllowedHosts": "*"
}
We set the formatting to single line and add the timestamp to get something like this:
NOTE - When I changed the appsettings file, I saw that the messages that came from the app were properly formatted and the ones that I had introduced were not. That's because, in the original code, I have created a different logger that doesn't get its messages for appsettings.json (the default logger created by the Asp.NET app does that automatically). The simplest and cleanest solution was to use the default logger, by changing this code:
var logger = LoggerFactory.Create(config =>
{
config.AddConsole();
}).CreateLogger("CustomerApi");
with this one:
var logger = app.Logger;
If we want more info for the log, we can set the formatter name to json and IncludeScopes to true:
As you can see, in the State object, you have the count, method name, line number and even the original format of the messages. In the Scopes object you have data about the message, connection id and even the request path for the request.
We can continue adding messages for logging:
using System.Runtime.CompilerServices;
public static partial class LoggerExtensions
{
[LoggerMessage(EventId = 100, Level = LogLevel.Information,
Message = "{methodName}({lineNumber}) - Retrieved {Count} customers")]
public static partial void ShowRetrievedCustomerCount(this ILogger logger, int count,
[CallerMemberName] string methodName = "", [CallerLineNumber] int lineNumber = 0);
[LoggerMessage(EventId = 404, Level = LogLevel.Information,
Message = "{methodName}({lineNumber}) - Customer {customerId} not found.")]
public static partial void CustomerNotFound(this ILogger logger, string customerId,
[CallerMemberName] string methodName = "", [CallerLineNumber] int lineNumber = 0);
[LoggerMessage(EventId = 200, Level = LogLevel.Trace,
Message = "{methodName}({lineNumber}) - Retrieved customer {customerId}")]
public static partial void RetrievedCustomer(this ILogger logger, string customerId,
[CallerMemberName] string methodName = "", [CallerLineNumber] int lineNumber = 0);
[LoggerMessage(EventId = 300, Level = LogLevel.Information,
Message = "{methodName}({lineNumber}) - Creating customer {customerId}")]
public static partial void CreatingCustomer(this ILogger logger, string customerId,
[CallerMemberName] string methodName = "", [CallerLineNumber] int lineNumber = 0);
[LoggerMessage(EventId = 302, Level = LogLevel.Trace,
Message = "{methodName}({lineNumber}) - Created customer {customerId}")]
public static partial void CreatedCustomer(this ILogger logger, string customerId,
[CallerMemberName] string methodName = "", [CallerLineNumber] int lineNumber = 0);
[LoggerMessage(EventId = 400, Level = LogLevel.Information,
Message = "{methodName}({lineNumber}) - Updating customer {customerId}")]
public static partial void UpdatingCustomer(this ILogger logger, string customerId,
[CallerMemberName] string methodName = "", [CallerLineNumber] int lineNumber = 0);
[LoggerMessage(EventId = 402, Level = LogLevel.Trace,
Message = "{methodName}({lineNumber}) - Updated customer {customerId}")]
public static partial void UpdatedCustomer(this ILogger logger, string customerId,
[CallerMemberName] string methodName = "", [CallerLineNumber] int lineNumber = 0);
[LoggerMessage(EventId = 500, Level = LogLevel.Information,
Message = "{methodName}({lineNumber}) - Deleting customer {customerId}")]
public static partial void DeletingCustomer(this ILogger logger, string customerId,
[CallerMemberName] string methodName = "", [CallerLineNumber] int lineNumber = 0);
[LoggerMessage(EventId = 502, Level = LogLevel.Trace,
Message = "{methodName}({lineNumber}) - Deleted customer {customerId}")]
public static partial void DeletedCustomer(this ILogger logger, string customerId,
[CallerMemberName] string methodName = "", [CallerLineNumber] int lineNumber = 0);
}
As you can see we have some messages who have the Information level and others that have the Trace level. We can add now the log messages in the code:
using Microsoft.EntityFrameworkCore;
var builder = WebApplication.CreateBuilder(args);
builder.Services.AddEndpointsApiExplorer();
builder.Services.AddSwaggerGen();
builder.Services.AddDbContext<CustomerDbContext>();
var app = builder.Build();
app.UseSwagger();
app.UseSwaggerUI();
var logger = app.Logger;
using (var scope = app.Services.CreateScope())
{
var dbContext = scope.ServiceProvider.GetRequiredService<CustomerDbContext>();
await dbContext.Database.EnsureCreatedAsync();
}
app.MapGet("/customers", async (CustomerDbContext context) =>
{
var customers = await context.Customer.ToListAsync();
logger.ShowRetrievedCustomerCount(customers.Count);
return Results.Ok(customers);
});
app.MapGet("/customers/{id}", async (string id, CustomerDbContext context) =>
{
var customer = await context.Customer.FindAsync(id);
if (customer == null)
{
logger.CustomerNotFound(id);
return Results.NotFound();
}
logger.RetrievedCustomer(id);
return Results.Ok(customer);
});
app.MapPost("/customers", async (Customer customer, CustomerDbContext context) =>
{
logger.CreatingCustomer(customer.Id);
context.Customer.Add(customer);
await context.SaveChangesAsync();
logger.CreatedCustomer(customer.Id);
return Results.Created($"/customers/{customer.Id}", customer);
});
app.MapPut("/customers/{id}", async (string id, Customer customer, CustomerDbContext context) =>
{
logger.UpdatingCustomer(id);
var currentCustomer = await context.Customer.FindAsync(id);
if (currentCustomer == null)
{
logger.CustomerNotFound(id);
return Results.NotFound();
}
context.Entry(currentCustomer).CurrentValues.SetValues(customer);
await context.SaveChangesAsync();
logger.UpdatedCustomer(id);
return Results.NoContent();
});
app.MapDelete("/customers/{id}", async (string id, CustomerDbContext context) =>
{
logger.DeletingCustomer(id);
var currentCustomer = await context.Customer.FindAsync(id);
if (currentCustomer == null)
{
logger.CustomerNotFound(id);
return Results.NotFound();
}
context.Customer.Remove(currentCustomer);
await context.SaveChangesAsync();
logger.DeletedCustomer(id);
return Results.NoContent();
});
app.Run();
After changing the appsettings file to show the trace messages and give a more succint report:
{
"Logging": {
"LogLevel": {
"Default": "Information",
"Microsoft.AspNetCore": "Warning",
"Microsoft.EntityFrameworkCore": "Warning",
"CustomerService": "Trace"
},
"Console": {
"FormatterName": "simple",
"FormatterOptions": {
"SingleLine": true,
"IncludeScopes": false,
"ColorBehavior": "enabled",
"JsonWriterOptions": {
"Indented": true
}
}
}
},
"AllowedHosts": "*"
}
We get this:
As you can see, we have standard messages, with the correct event ids and levels and we have the methods and line numbers, without having to bother with message formatting and setting values for the event ids or levels.
The full source code for this article is at https://github.com/bsonnino/EnhancedLogging