Skip to content
Bruno Sonnino
Menu
  • Home
  • About
Menu

Using C# source generation for enhanced logging

Posted on 29 July 2023

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 ILogger instance 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 this for the ILogger parameter. This is not mandatory, but I wanted to make this method as an extension method, so it can be called with logger.ShowRetrievedCustomerCount(10)
  • The method must be void
  • I am passing the method name and line number, obtained with the attributes CallerMemberName and CallerLineNumber

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

Leave a Reply Cancel reply

Your email address will not be published. Required fields are marked *

  • May 2025
  • December 2024
  • October 2024
  • August 2024
  • July 2024
  • June 2024
  • November 2023
  • October 2023
  • August 2023
  • July 2023
  • June 2023
  • May 2023
  • November 2022
  • October 2022
  • September 2022
  • August 2022
  • June 2022
  • April 2022
  • March 2022
  • February 2022
  • January 2022
  • July 2021
  • June 2021
  • May 2021
  • April 2021
  • March 2021
  • February 2021
  • January 2021
  • December 2020
  • October 2020
  • September 2020
  • April 2020
  • March 2020
  • January 2020
  • November 2019
  • September 2019
  • August 2019
  • July 2019
  • June 2019
  • April 2019
  • March 2019
  • February 2019
  • January 2019
  • December 2018
  • November 2018
  • October 2018
  • September 2018
  • August 2018
  • July 2018
  • June 2018
  • May 2018
  • November 2017
  • October 2017
  • September 2017
  • August 2017
  • June 2017
  • May 2017
  • March 2017
  • February 2017
  • January 2017
  • December 2016
  • November 2016
  • October 2016
  • September 2016
  • August 2016
  • July 2016
  • June 2016
  • May 2016
  • April 2016
  • March 2016
  • February 2016
  • October 2015
  • August 2013
  • May 2013
  • February 2012
  • January 2012
  • April 2011
  • March 2011
  • December 2010
  • November 2009
  • June 2009
  • April 2009
  • March 2009
  • February 2009
  • January 2009
  • December 2008
  • November 2008
  • October 2008
  • July 2008
  • March 2008
  • February 2008
  • January 2008
  • December 2007
  • November 2007
  • October 2007
  • September 2007
  • August 2007
  • July 2007
  • Development
  • English
  • Português
  • Uncategorized
  • Windows

.NET AI Algorithms asp.NET Backup C# Debugging Delphi Dependency Injection Desktop Bridge Desktop icons Entity Framework JSON Linq Mef Minimal API MVVM NTFS Open Source OpenXML OzCode PowerShell Sensors Silverlight Source Code Generators sql server Surface Dial Testing Tools TypeScript UI Unit Testing UWP Visual Studio VS Code WCF WebView2 WinAppSDK Windows Windows 10 Windows Forms Windows Phone WPF XAML Zip

  • Entries RSS
  • Comments RSS
©2025 Bruno Sonnino | Design: Newspaperly WordPress Theme