Log Better

Overview

Logging is one of the main pillars of an application development and application observatory. Although (almost) all developers know this concept nowadays, I have seen many application teams suffer from good logging.

Although this is a general concept in any platform and programming languages, in this article I play around .NET CORE, SeriLog and Splunk. Feel free to replace them with their alternatives.

There are four different aspects when we do logging. This article mostly focuses on #2.

1. Logging Framework
2. When and what to log
3. Testing
4. Observatory/Search Tool

Choosing a logging framework is a one time activity for an application and usually we don't want to change it. I have not experienced changing the logger framework while the application is in production, but that doesn't mean that it doesn't exist. .NET has an abstraction layer around logging so, technically, you are able to change the application instrumentation to any logger framework at any time of the application lifecycle.

When and what to log is something that developers who implement the logic should take care of. It varies based on application, architecture, team conventions and more.

Testing log events is something that might get missed easily. I just can say it is always worth it to test the code including log events. They eventually save some time down the road. This article is not discussing this matter. I hope that I cover it in a different one.

There are several search tools that they can parse the logs and give us the ability to filter, search and many more. This article is not focusing on what tool to use, I just put Splunk as a powerful tool doing it.

Structure Logging

Structure logging is thinking of log events as objects and not simple texts. It allows advanced logging tools like Splunk or ELK to index log events based on their properties so that it makes it easier to query them and find them easier. 

To make it easy to imagine, think of a log entry as a dynamic object that can have any number of properties.

Unstructured:

[2018-04-23T18:25:43.511Z] Something good happened, server \"SRV-7\", ipAddress \"192.168.0.156\"        

Structured:

{
  _time: 2018-04-23T18:25:43.511Z,
  message: "Something good happened",
  server: "SRV-7",
  ipAddress: "192.168.0.156"
}        

Of course you should not focus on coding logs. You should not maintain the logger code. There are tons of them out there. Just use the good one in your app and it does the job for you.

Some tools (like Splunk) parse unstructured logs and make them structured. They are good up to certain level when logs have some patterns like CSV, fixed positioning, convention and so on

Log Levels

Log everything that you can! However you don’t want to pollute your logs with unnecessary text. But what is necessary and what is unnecessary?

The answer is "it depends". In regular day to day production applications, we probably don’t need a lot of verbose log entries. On the other hand, if we debug a production issue, those many logs might be critically helpful.

When developers write the code, they should be able to cover both of the above scenarios – and many more. Log LEVEL is the way to give them the ability to choose the importance of the event. Later, it would be up to the hosting environment and/or configuration to filter the logs.

Therefore, log any hint that the person who troubleshoots can find the issue quicker. Just make sure you are choosing the best level. 

Some good practices are:

• If the application can’t do anything because of a serious issue, log FATAL before it crashes. Log any sort of information with your entry that might be helpful. 
• Log all exceptions in detail. If an application cannot handle an exception, it should log it. Even if it can handle it, it should log it.

In .NET Core, you can use middleware to catch all the exceptions instead of "try...catch" them one at the time. 

• If the scenario that you are logging is unexpected and there is no way to get around it, log ERROR
• If the scenario that you are logging is unexpected but there is a way to get around, log WARNING. 
• If you want to leave a footprint to make sure you can audit when a scenario occurred, log INFORMATION. Also if you are logging statistical information, you usually want to have them at INFORMATION level. 

Some of the statistics, however, are good for the debugging purposes only. 

• If the scenario is an expected issue from other systems or from data, log WARNING.
• A good hint to the app support team is DEBUG log entries. DEBUG logs also help developers to catch impacts of different components during their integration.
• Use VERBOSE for really hard to find issues. Usually you don’t do this unless you are changing the code to find out a really-hard-to-find issue. 

Making the decision what level to pick is up to the engineer who writes the logic. The better log level, the better way to find issues and troubleshoot the application.

Filter out sensitive information! You should never log sensitive information in any condition in your application.

Scopes

When working with structured logging, the logging framework will give you the ability to add properties to your entries in different scopes

Event scope

When you log an event, you can add additional information as a property. Here are some examples:

Log.Information ("Order submitted successfully. {OrderNumber}", "o134-872");

Log
  .ForContext("OrderNumber", "o134-872")
  .Information ("Order submitted successfully.");        

Block scope

Advanced logging frameworks give the developer the opportunity to add a property within a using statement. That means all the logging entries within the using brackets and all the nested method calls in it will have that property and its value.

The value of the property can be overwritten in the inner scope

Serilog does the job like this:

{
  using(LogContext.PushProperty("OrderNumber", "o134-872")
  {
    Log.Information("Order submitted successfully.");

    _emailService.SendNotification();
  }
}

...

class EmailService
{
  void SendNotification()
  {
    Log.Information("Notification has been sent.");
  }
}        

In the above example, both log entries will have the same property OrderNumber:

{
  "message": "Order submitted successfully.",
  "orderNumber": "o134-872"
}
 
{ 
  "message": "Notification has been sent.",
  "orderNumber": "o134-872"
}        

.NET Core logging framework does the same job in a different form:

using (_logger.BeginScope("using block message")
{
  ...
 
  _logger.LogInformation(MyLogEvents.GetItem, "Getting item {Id}", id);

  ...
}        

Application

Some frameworks have a wrapper around the using statement and make it easier to add property at the wider scope. Say in ASP.NET Core, you may use a middleware to add the requested IP address to all log entries.

Advanced Topics

Enrichers 

Serilog has the concept of enrichers which does the similar job as middleware practice explained above except cleaner.

var log = new LoggerConfiguration(
    .Enrich.WithThreadId()
    .WriteTo.Console()
    .CreateLogger();)        

You can even have your own Enrichers

var log = new LoggerConfiguration(
    .Enrich.WithBuildNumber()
    .Enrich.WithServerName()
    .Enrich.WithCloudInstanceIpAddress()
    .CreateLogger();)        

Metrics

Like mentioned above, it's important to log some stat information. Framework can do some of these.

using (Operation.Time("Submitting payment for {OrderId}", order.Id))
{
    // Timed block of code goes here
}        

At the start of this disposable statement, a timer is set. When the dispose() method is called (end bracket), the framework logs the total elapsed time in an event property nicely.

Conclusion

There are many details when it is the matter of logging. Some are limited by infrastructure and framework. Some are open to choose by developers. The more knowledge of those details a team has, the better consistency shows up on the code. As a result, troubleshooting becomes easier and issues can be identified faster.