Improving logging output

December 13, 2021

In this post, we will look at how to improve the log output. Whether by embellishing entries with contextual data or improve searchability using structured logging. We have already seen the basic usage of logging methods. Let’s start by adding some timestamp information to our logging output.

using var loggerFactory = LoggerFactory.Create(builder =>
{
    builder.AddSimpleConsole(co =>
    {
        co.TimestampFormat = "[HH:mm:ss] ";
    });
});

var logger = loggerFactory.CreateLogger<Program>();

logger.LogInformation("Log info with time stamp");

In the sample code above a timestamp format was defined. Also, note that AddSimpleConsole is used since the AddConsole options method overload is marked obsolete. Options can also be set via a configuration file. Notice also that the logger was created using the generic overload. In this case, a fully qualified type name will be used to create a category. It is also the more standard way of using logging, especially when used with dependency injection. There you will often see classes requesting a logger with a category for the class, or in other words, a class MyClass would request ILogger<MyClass> as one of the constructor parameters. The above code will produce the following output:

[17:53:49] info: MSLoggingInConsoleApp.Program[0]
      Log info with time stamp

Another thing to note, when logging, is how to log exceptions. All the LogXXX overloads provide an overload that accepts an exception as input. When using those overloads, the exception message and stack trace will be shown in the log. This reduces the need for manually creating such messages.

try
{
    ThrowTestException();
}
catch (Exception exception)
{
    logger.LogInformation(exception, "Writing an exception");
}

Another thing one can do to embellish the log entries is to add an event ID to the log entry. ID is an integer value, which makes it easier to search for certain events in the log output. Again there is an overload available that takes an event ID.

logger.LogInformation(
  MyEventIds.HelloWorld, "Writing with event ID");

In the sample, I used a MyEventIds class as a container for event IDs in the application.

public static class MyEventIds
{
    public const int HelloWorld = 10;
}

Producing the following console output:

[07:52:35] info: MSLoggingInConsoleApp.Program[10]
      Writing with event ID

Notice the value 10 in the brackets. It is the same value as our MyEventIds.HelloWorld value.

Another way to improve contextual awareness of the log messages is to use scopes. Imagine that you have a set of methods that are being used in different parts of your application. By using scopes, you can pass this contextual information of which part of the application invoked the said method. It will append the information to every log entry within the scope. But to be able to use scopes, you first need to enable them in configuration, either in code or in the configuration file:

using var loggerFactory = LoggerFactory.Create(builder =>
{
  builder.AddSimpleConsole(co =>
  {
    co.IncludeScopes = true;
  });
}

To use the scopes, do the following:

using (logger.BeginScope("scope message"))
{
  logger.LogInformation("My scope log entry");
}

And produces the following output in the console:

info: MSLoggingInConsoleApp.Program[0]
  => scope message
  My scope log entry

Last but not least thing to know about logging is how to do structured logging. As mentioned in the link, the main idea behind structured logging is to provide both human-friendly text and still enable an easy search for parameters.

var someId = 10;
var someType = "structured";
logger.LogInformation(
  "Using structured logging with id {id} and {type}",
  someId, someType);

In the sample above, a message template was provided with named placeholders. Those are filled with matching arguments in order of appearance, meaning the first argument is matched to the first placeholder, the second argument to the second placeholder, etc. Resulting in the following console output:

info: MSLoggingInConsoleApp.Program[0]
  Using structured logging with id 10 and structured

To see the full benefit of structured logging, let’s replace simple console with json console.

using var loggerFactory = LoggerFactory.Create(builder =>
{
  builder.AddJsonConsole();
});

This outputs the following:

{
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "MSLoggingInConsoleApp.Program",
  "Message": "Using structured logging with id 10 and structured",
  "State": {
    "Message": "Using structured logging with id 10 and structured",
    "id": 10,
    "type": "structured",
    "{OriginalFormat}": "Using structured logging with id {id} and {type}"
  }
}

Now imagine you store such a result into a document store database (e.g. Elasticsearch). Data stored in such format makes the search in your log for entries with e.g. type of structured much easier.

Resources: