ERNI Technology Post No. 50: Using log4Net in .NET projects

Probably every Software developer has used logging in some way during his career and also knows how to use one of the many frameworks to write messages into a log. But just because someone can write a log message does not mean that he knows how to use a logging framework. In fact I’ve worked on several projects where a logging framework was used but actually did not yield a lot of benefit, it was just kind of there.

This article will show you how to get the most out of Apache’s log4net logging framework in your .NET project. This will help during development when you have to identify problems in your code or to monitor the performance and health of your application after the project has gone into production.

We once worked on a project where we tried to make a mobile phone talk to another piece of hardware through an SSL connection; however, we were unable to establish a connection. We were sure that the data we sent was correct, so we spent three days trying to find out what the problem was until deciding to log the data that was sent right before it went out over Wi-Fi. It was at that point that we discovered we’d sent incomplete data, despite having been sure that it was correct.

So after we fixed the issue, we asked ourselves: Why did we spend three days on this issue when we could have solved this problem in a matter of hours with logging? I also realised that I had similar problems in other projects. Although we used logging, we only started to care about it when we encountered a problem and had to extend the log messages in order to find the root cause. But a good log should already contain the necessary information to help you fix the problem. In this article I will show you some tricks that you can use together with the log4net logging framework to create better logs.

What can log4net do for you?

If you are new to the log4net framework, here is a short overview what it can do for you. The log4net framework is a small logging framework that allows you to easily write log messages to various output formats like text files or databases. It is maintained by the Apache Software Foundation and available through the Apache License 2.0. This means you can use it free of charge. As I stated earlier, it can store log messages in various output formats like text files, databases, Windows Event Log and is even capable of sending the messages over the network using SMTP or UDP. The configuration can be loaded from an XML file so you don't have to change any lines of code when you want to switch the output format.

Why it is a good Idea to use log4net?

Since log4net is free, you don't have to pay any licence fee to use it in your project. So, even if for some reason it is decided to no longer use this framework in your project, it will not have an impact on the project’s budget.

Secondly, it is very easy to use. The programming interface is kept very simple and allows you to write a message to the log with only a single line of code. It is also very straight forward and it shouldn’t take long for a developer to get used to it. At the beginning, it will take some time to properly set up the framework for your project, but after that, it won’t require a lot of work to maintain.

In addition, Log4net also doesn’t have any side effects. Imagine there is something wrong with the logging framework, for example, the file in which the messages are written cannot be accessed due to restrictions of the operating system. In such cases, log4net will never throw an error, instead it just won’t produce a usable log. So the risk that log4net has a negative impact on the stability of your application is very low.

Common mistakes when logging

Before we take a look at how you can use log4net, let's discuss some common mistakes developers make when they are using this framework.

Don't write your own logging code

A lot of times developers write a small wrapper class through which log4net is used to make it easier for them to write log messages in the code. Of course it seems to be a good idea to decouple the framework from the code, but the clear advice here is: Don't do this!

As mentioned before, the programming interface of log4net is designed to be very easy to use and does not have an impact on the stability or the performance of your application. If you write a wrapper class, the benefits might get lost if you do not properly test your wrapper class. Thus, it might happen that you get exceptions when you try to write messages to the log which could subsequently make your application stop working.

Impacts on performance and stability

Log4net allows you to compose logging statements in a similar way to the String.Format method of the .NET framework by using a hard coded template string that contains placeholders for runtime values. In .NET, working with strings is an expensive operation that can lead to noticeable performance issues when used too often. That's why log4net will only create the final message once it has confirmed that it will actually be written to the log (for example, it has write access to the log and the message has the right log level). So as long as the framework is used directly, performance loss through logging will only be an issue if a lot of messages are written in a short period of time. But of course it might happen that developers use the framework improperly. Here are three examples how a message can be written to the log. The first and second will have an impact on the performance because the message is created immediately, while the third one leaves this task to log4net:

log.Warn("Adding this message for " + sender.ToString() + " to the log will impact performance");

log.Warn(string.Format("Adding this message for {0} to the log will impact performance", sender));

log.WarnFormat("Framework will create message for {0}", sender);

The first line of code also causes a problem if the object 'sender' is null. If this is the case it would have an impact on the stability of the application, while on the third line of code, the framework will first check if the supplied object is not null before calling the 'ToString' method.

Dependency on the framework

Every class that uses log4net has a direct dependency on its library, that is why a lot of developers try to break this dependency through a wrapper class (as mentioned before, you should not do this). Of course this goes against fundamental principles in software development and it is understandable why developers do not like such dependencies. However, this is also one of the reasons why log4net covers a wide range of functionality and allows you to change the behaviour of the code through the configuration without the developer having to actually change the code itself. Therefore it is acceptable to have a direct dependency to the log4net framework from your classes.

What needs to be considered when using log4net?

Before you write your first logging statement, you should take some time to document how you intend to use log4net in your project. The best place to do this is in the Software Architecture Document. There you should explain why you are using log4net (is it only for debugging purposes or do you also want to gather other information) and where the logs of your application are stored. One thing I found very useful in the past was to define how the developers should use the different log levels that log4net offers. You might think that the developers should use the log levels as they see fit, but it actually makes sense to define this at the project level. Here is an example why:
An application can produce different kinds of errors. There are fatal errors that cause the application to stop working, in these cases there is nothing that can be done to recover. Then there are errors which are expected and your application can recover from them, like when you try to load data from a web service that is not available. Instead of crashing, your application can instead work with an older set of data that is loaded from a cache. Additionally, there are also errors that may not make your application crash, but are unforeseen and therefore can lead to unexpected behaviour. The following example illustrates this:

log4net suggestions

Here you expect that there are only two different values in the enumeration. But what happens if the enumeration is extended with 'PlanC'? If the developer forgets to handle the new state in the switch statement, it is clearly a bug in the code and must be fixed. So here it makes sense to use a different log level to indicate that there is an issue with the code.

If you use the same log level every time something happens which was unexpected, you will ultimately be able to know exactly how to react if you find such a message in your log. However, if you leave this decision to the developers, you don't really know if a message with level Warning needs to be addressed by the team or if you can ignore it.

Best Practices

How log4net can be used to best effect depends on the type of application that is being developed. For example, in a desktop application the logical flow is mostly clear and it is quite easy to find code errors, while on the other hand, web services often work stateless, and how the code gets executed depends on the parameters that where supplied to the service. Therefore, it also makes sense to have two different logging approaches for these kinds of projects.

Desktop App

Desktop applications are part of the “standard scenario” for using log4net in a project. Most of the time it only makes sense to log errors and debug statements, for example when the application does not have the privileges to write to certain files or if it cannot load data from the configuration file. It is also a good idea to log when you load data from outside of the application (except configurations) which will have an impact on how your code behaves.
In larger applications you can add functionality that allows the end-user to create and send a problem report to the developers containing the most recent log files or other information that is needed for debugging.

Here is an example configuration file for your application:

Desktop Application

This will write the local time, the log level and logger name, thread id and log message to a text file in the Windows temp folder.
Notice the pipe '|' character that is used to separate the different parts of the log message from the others. This will make it easier to read the raw log file such as when you use a space or tabs to separate the parts. It will also allow you to automatically process the log file, for example when you import the messages into Microsoft Excel. This is not possible if you use spaces or other characters that are likely to also appear in the log message.

Web Service/Website

Logging in web services (and also websites) works similar to desktop applications. The logs should be stored as text files in a protected folder on the webserver. Log rotation should be set to an hour, because there will likely be a lot more messages written to the log than with a desktop application.
In web services you should log not only application errors and debug messages, but also the state of connected system. For example, if your web service is loading data from another service or a database, every time you successfully load data from it you should write a message to the log that the connection is working. If the connection is broken, you can log an error message. You can then define that the messages from this logger are written directly to the Windows Event Log. This way you get a very basic monitoring system that can alert the server administrator if a connection is broken. Here is a configuration example for web services:

Web Service

As you can see, this defines two log appenders, one for the local log file which catches all messages named ‘FileAppender’ and one for the Windows Event Log which only catches messages from loggers in the specified namespace. This way you can redirect all log messages coming from the service interfaces to the event log.

Framework

Logging in a framework requires a different approach to what is written to the log. The program flow in a framework is not as clear as in a desktop application or a web service, because you cannot exactly know how it is used by other developers. That is why it makes sense to log every call to one of the API methods in your framework so that the calling sequence can be backtracked.
Although I stated that it is not a good idea to write a wrapper class, it might actually make sense to do this for a framework, to make logging easier and to produce unified log messages. But be aware that this code has to be tested very thoroughly to make absolutely sure it won't introduce a new source of errors into your framework.

You also don't have to worry about the configuration of log4net, since this will be defined in the application that uses your framework.

Distributed Systems

In distributed systems there are two approaches as to how messages should be logged: First there should be a local log for every subsystem in order to log errors that only affect this subsystem.
Second, there should be a logging service in your system where all messages are stored in a centralized log. Every subsystem can then send error messages to the logging service, which makes it easier to track down problems that affect the whole system. Also, it is much easier to read the logs because all messages are stored sequentially in the order in which they arrived. The different subsystem might not have their clocks synchronized which could make it difficult to understand in which order the messages were generated when you only look at the local logs. A logging service can overcome this problem because it uses its own clock for logging the exact time a message was entered into the log.

You can download log4net from the Apache logging services webpage which also offers the same logging framework for other programming languages: https://logging.apache.org/

posted on 25.03.2015
Categories: 
by: Roman Ledermann