Logging Best Practices

In this article I will cover the best practices of logging in terms of the following concerns, regardless of what logging framework we use:
1- What to log
2- How to choose logging levels
3- Where to log

What to log

First of all logging is not a constant forward process. You don’t have to log all you need and then stop touching it. It can be an ongoing process and you can refactor your logging codes as your needs. Although we don’t have to write every possible event of our application upfront just in case we might have need it in future, there are some minimum events that we should log at first place.
All errors and critical conditions should be logged. It doesn’t mean that we should log an error in every Catch clause, because whether or not the caught exception is an error to log, depends on what that exception is and how you are going to handle it. For example your Catch clause might have caught a predicted “Access Denied” exception and have made the appropriate decision. This is not considered as an error but a lower log level like Debug never harms. Any unusual circumstances should be logged even if they don’t effect the application. Consider that the last example is not considered as an unusual circumstance either. It is also a good idea to log the starting point and end point of every process. Ideally if we have singly responsible methods, that would be logging at the beginning and end of each method. We don’t have to log every single parameter of each method but we can log some critical information such as endpoint URLs, connection strings or IDs. We can add more debugging logs later on if we need to. Never worry about too much logs, because almost all of the logging frameworks allow you to disable your logs partially. You can filter them based on the type for which you have logged or the level of your logs. So it is important to name your loggers after their surrounding types or at least give them a meaningful name, as the logger names will later be used for grouping and filtering the logs. It is also crucial to choose appropriate logging levels.

How to choose logging levels

Although logging frameworks allow us to have as many custom logging levels as we need, there are usually several default logging levels that are mostly used:
Fatal: Usually the highest level. Used when a problem stops the application’s functionality. This kind of errors usually happen because of unexpected circumstances for which no alternative solutions are provided. For example, no disk space, network disconnection or any unexpected circumstances which stops the application.
Error: This level is used when an error occurs but it is handled and it doesn’t interrupt the application. It may cause some minor problems or may lead to some consequences in the future. For example a connection to the master database is refused and we redirected the request to the slave to handle the issue.
Warn: For logging unusual circumstances that need consideration or they may lead to future problems. Low disk space is an example which may needs a warning level log.
Info: We use this logging level for monitoring the application’s process. It should be so that when someone reads the logs they can realize what is going on in the application. They shouldn’t contain debugging data or repeated information. So It’s not a good idea to use Info logging level in long loops.
Debug: This is the lowest logging level and it usually contains too much information that we often tend to filter this level out and use it only while debugging the application. It can contain any details that normally we don’t need to see in the logs.

Info or Debug

It is sometimes confusing whether to use Info or Debug. One of the common mistakes is that some developers use debug level for logging of dependencies. For example when a business object is using a data access object which needs to log some database operations, it may look like the data access object should use the debug level as it is serving a lower level functionality. However, when we choose the logging level for a component, we should consider that component in isolation. Any class can be a dependency for a higher level type and at the same time it may depend on other lower level components. When we read the logs we can filter only those components that we need to monitor or debug. So the lower level types should also have their own levels of Info and Debug. This is easier to handle when the application [concerns are separated](http://en.wikipedia.org/wiki/Separation_of_concerns "SoC") into individual classes. Otherwise you will have to consider a lower priority for some of the multiple concerns which are being addressed in a [single class](http://en.wikipedia.org/wiki/God_object "God Class") and choose Debug level for them to distinguish them from the main concerns of the same class.

Where to log

The easiest way to log is logging in between your code. But ideally we should consider that each object should have its own concern and logging is yet another concern. So we should separate it and put it somewhere else. Since logging is not limited to a specific layer of the application, it is a cross-cutting concern and two of the best practices to address such concerns are the Decorator design pattern and Aspect Oriented Programming (AOP). Both approach allow you to put your logging logic in separate classes and attach them to the type which is going to be logged. They allow you to log prior to, after, in case of success or in case of failure of a method. One may argue what if they need to log in the middle of a method. The answer is if each method is dealing with a single responsibility you won’t need that. The following code needs to be refactored so we won’t need to log in the middle of the Transfer method.

void Transfer(string source, string dest, Money amount) { log.Info("Transferring..."); log.Info("Debiting {0}...", source); ... // Debiting implementation log.Info("{0} debited.", source); log.Info("Crediting {0}...", dest); ... // Creddiing implementation log.Info("{0} debited.", dest); log.Info("Transfer finished."); }

The followoing shows how to refactor the above code:

void Transfer(Account source, Account dest, Money amount) { log.Info("Transferring..."); source.Debit(amount); dest.Credit(amount); log.Info("Transfer finished."); }

The Debit and Credit implementation should be moved to the Account object.

public class Account { public string Number {get;set;}

public void Debit(Money amount) { log.Info("Debiting {0}...", this.Number); ... // Debiting implementation log.Info("{0} debited.", this.Number); }

public void Credit(Money amount) { log.Info("Crediting {0}...", this.Number); ... // Creddiing implementation log.Info("{0} debited.", this.Number); } }

Another moral of the above example is that the calling code should not take care of logging for the called method. Each method should log their own responsibilities only.