Orko's Blog: March 2013

Hi! Today, I would like to show you a sample logging implementation in .NET, with the popular logging library "log4net". log4net, for me and many other developers, is a fancy, functional and handy logging tool. Though, it may sometimes be a big hassle, unless you do configure or use it correctly. My example application is a sample n-tier WCF Application, however, the log4net configurations and codes in our sample can easily be adapted to different types of applications.

Why do I need logging?

Before we proceed further, I would like to stress on the importance and necessity of logging. But first, let me start with its definition :

Logging is the process of recording application actions and state to a secondary interface.

We are recording application actions and state ... which actions and what state should we record? We are recording these to a secondary interface, which could be a file, database, Web-Service, email, etc... The nature of the interface is not so important, what is important is that this is a secondary interface. The user who sees this interface, the support guy looking at the application log, does not have access to the application's primary interface. This means that what is detailed in this log is very important; it is often the main source of information when diagnosing a problem.

Logging is a secondary software development activity, which, most of the time, can be undermined by the developers. Actually, the importance of the logging is best understood when a big software application becomes a product and the clients start using it. In this case, the logs will be extremely valuable for the support guys. They will provide maintenance, report or even resolve the bugs all by the help of application logs. However, an application log may also be used for creating statistics relating to the application usage. For example, a log file may be used to determine the number of concurrent users as a measure of performance, or it could be used to explore usage patterns for market research purposes.

Well, not only a product but even also a Proof Of Concept Software Application might need logging. Logs do not only help others but they do also help us (developers). Logs simply are our debugging tool. They help developers do fast debugging. Besides, debuggers mostly fail in concurrent programs where several threads are running simultaneously. In such cases, logs save our lives.

log4net

log4net is the most popular logging tool for .NET. It is powerful , handy and extensible. log4net is a port of Apache log4j framework (for Java) to the Microsoft .NET runtime. In spite of the fact that logging offers many advantages, it does have its drawbacks. It can slow down an application. If too verbose, it can cause scrolling blindness. To alleviate these concerns, log4net is designed to be reliable, fast and extensible.The log levels, loggers, appenders and layouts are important features of log4net which provide flexibility. I will not elaborate on log4net and its features, bacause it will take quite long time. For more information about this handy tool, please visit its homepage.

Well, I guess this much story telling is enough for this post. Now let us have a closer look at our sample application.

Sample log4net Implementation for an N-Tier WCF Application

Before we analyze the log4net implementation, we should first grasp the n-tier structure of our WCF Application. The application is developed with C# language in .NET 4.0 Framework with Visual Studio 2010. The general Solution Explorer View is as follows:

Our WCF Application consists of several layers (note that each layer is implemented as projects). We have Service Layer "Log4NetDemo.Service", where we have our WCF Web Services. Underneath, we have a sample Business Layer "Log4NetDemo.Business". We implement our business logic here. Since it's just a simple demo, Business Layer here does not implement a complicated Business Logic. It rather coordinates the data access of Services. Underneath, we have the Repository Layer, "Log4NetDemo.Repository", which simply is our Data Access Layer. "Log4NetDemo.Domain" is where we hold our domain model entities and .edmx file. Please note that our application uses "Entity Framework" for Data Base access.

To test this WCF Application, we would need a test environment. Hence, I added "Log4NetDemo.Test" Project, which basically involves a [TestClass] and the test class tests the methods that our service exposes. "Log4NetDemo.ServiceReferences" is another project for service references. In order to consume the WCF Web Service, "Log4NetDemo.Test" uses its "dll" as a reference.

log4net is a dll. We should add this dll as a reference to each project where we want to use it.

The next thing to do is to configure log4net. We might use "web.config" or an external configuration file. In this example, I used web.config for the log4net configuration.

The following configuration segment is to add the log4net configuration to your web.config file :

<?xml version="1.0" encoding="UTF-8"?>

</configSections>

Here is a basic log4net configuration having one file appender with a user defined layout, one default root logger and one user defined logger :

</layout>

</appender>

<root>

<appender-ref ref="RollingFile" />

</root>

</logger>

</log4net>

Note that, with an extra setting inside the code, all our classes in "Log4NetDemo.Repository" layer will be the children of Log4NetDemo.Repository Logger. They will inherit their parent logger's features and hence only log the INFO or above level logs.

I come across developers who think that they have to add seperate log4net configuration file for each project in a solution. This is completely a wrong idea. For such a WCF Application that includes several projects, configuring log4net inside the web.config file would be enough.

If we are OK up to here, I want to make one step forward. log4net allows multiple appenders. In my sample application, I don't only want to store my logs in a file, but I also want to keep some special application states, let's say, the state when I insert a new item into the database. In order to achieve this, I would need AdoNetAppender. Here is the full log4net configuration of web.config:

</layout>

</appender>

</parameter>

</layout>

</parameter>

</layout>

</parameter>

</layout>

</parameter>

</layout>

</parameter>

</layout>

</parameter>

</parameter>

</appender>

<root>

<appender-ref ref="RollingFile" />

</root>

</logger>

<appender-ref ref="DBAppender" />

</logger>

</log4net>

DBLogger is defined in order to append logs to database. We'll use it when we want to log our application state in the database. In order to store the logs in database, we will need a database table as well. It will simply look like this :

-- Creating table 'Log'

CREATE TABLE [dbo].[Log] (

[Id] int IDENTITY(1,1) NOT NULL,

[Date] datetime NOT NULL,

[Thread] nvarchar(255) NOT NULL,

[Level] nvarchar(50) NOT NULL,

[Logger] nvarchar(255) NOT NULL,

[User] nvarchar(50) NULL,

[Message] nvarchar(4000) NOT NULL,

[Exception] nvarchar(2000) NULL

);

Now that we have the necessary log4net configuration to store our logs both in a file and a database. So we can start coding. The first thing we are supposed to do is to load the configuration in application startup. In Web Forms, there is "global.asax" file, in which the application start up can be handled. We have the chance to manually add "global.asax" file in WCF. But, in our sample application, I'd rather define a base service class and load the configuration in its constructor. All services will be inherited from the base class, and all service constructors will call the parent constructor. To sum up, I'll load the configuration when the service is initialized. Below, you can see our service implementation.

Here is our service base class in ServiceBase.cs :

using log4net.Config;

using log4net;

using System.IO;

namespace Log4NetDemo.Service {

public class ServiceBase {

private readonly ILog log;

public ServiceBase() {

//Load log4net Configuration

XmlConfigurator.Configure();

//Get logger

log = LogManager.GetLogger(typeof(ServiceBase));

//Start logging

log.Debug("ServiceBase Constructor Call");

}

Our sample WCF Service Contract is as follows :

using System.ServiceModel;

namespace Log4NetDemo.Service {

[ServiceContract]

public interface IService1 {

[OperationContract]

int GetValue();

[OperationContract]

void SetValue(int? value);

}

And here comes the service implementation :

using System;

using log4net;

using log4net.Config;

using Log4NetDemo.Business;

namespace Log4NetDemo.Service {

public class Service1 : ServiceBase, IService1 {

private readonly ILog log;

public Service1() : base() {

//Get logger for Service1

log = LogManager.GetLogger(typeof(Service1));

}

public int GetValue() {

try {

log.Info("Entering GetValue()");

Business1 business = new Business1();

if (business != null) { log.Debug("Business initialization is OK"); }

int value = business.GetBusinessValue();

log.Info("Exiting GetValue()");

return value;

}

catch(Exception ex) {

log.Error("Exception = ", ex);

return Int32.MinValue;

}

public void SetValue(int? value) {

try {

if (value.HasValue) { log.InfoFormat("Entering SetValue(), value = {0}", value.ToString()); } else { return; }

Business1 business = new Business1();

if (business != null) { log.Debug("Business initialization is OK"); }

business.SetBusinessValue(value.Value);

log.Info("Exiting SetValue()");

} catch (Exception ex) { log.ErrorFormat("Exception = {0}", ex); }

}

We're done with the service layer. We can go on with the business layer now. Before we proceed, please keep in my mind, this sample application is prepared only to show you how to use log4net in an n-tier WCF .NET Application. Business Layer implementation in terms of log4net is nothing new. If you want you can skip this section and pass to Repository Layer in order to see how database logging happens.

Here comes the BusinessBase.cs :

using log4net;

namespace Log4NetDemo.Business {

public class BusinessBase {

//Get Logger

private readonly ILog log = LogManager.GetLogger(typeof(BusinessBase));

public BusinessBase() {

log.Debug("BusinessBase Constructor Call");

}

}

And our sample Business Class is as follows :

using Log4NetDemo.Repository;

using log4net;

namespace Log4NetDemo.Business {

public class Business1 {

private readonly ILog log;

public Business1() {

//Get Logger

log = LogManager.GetLogger(typeof(Business1));

}

public int GetBusinessValue() {

log.Info("Entering GetBusinessValue()");

Repository1 repo = new Repository1();

if (repo == null) { log.Error("Repository initialization FAILS!!"); }

log.Debug("Repository initialization is OK");

int? value = repo.GetRepositoryValue();

if (!value.HasValue) { log.Error("Repository returns NULL!!"); }

log.Info("Exiting GetBusinessValue()");

return value.Value;

}

public void SetBusinessValue(int value) {

log.InfoFormat("Entering SetBusinessValue(), value = {0}", value.ToString());

Repository1 repo = new Repository1();

if (repo == null) { log.Error("Repository initialization FAILS!!"); }

log.Debug("Repository1 initialization is OK");

repo.SetRepositoryValue(value);

log.Info("Exiting SetBusinessValue()");

}

So far so good!! Now it's time to have a look at database logging. We have already defined "DBAppender" which is of type "log4net.Appender.AdonetAppender" and "DBLogger" which is assigned the "DBAppender". Let's see how we use them in Repository :

using log4net;

namespace Log4NetDemo.Repository {

public class Repository1 {

private readonly ILog log;

private readonly ILog dbLog;

public Repository1() {

//Get Logger

log = LogManager.GetLogger(typeof(Repository1));

//Get "DBLogger"

dbLog = LogManager.GetLogger("DBLogger");

//Set username

MDC.Set("user", "orko");

}

public int GetRepositoryValue() {

log.Info("Entering GetRepositoryValue()");

int? value = 1;

if (!value.HasValue) { log.Error("value is NULL"); }

else { log.Debug("value retrieval is OK"); }

log.Info("Exiting GetRepositoryValue()");

return value.Value;

}

public void SetRepositoryValue(int? value) {

if (value.HasValue) {

log.Info("Entering SetRepositoryValue(): value = " + value.Value);

//This log is stored in database.

dbLog.InfoFormat("Setting Repository Value: {0}", value.Value);

} else { log.Info("Entering SetRepositoryValue()"); }

if (!value.HasValue) { log.Error("value is NULL"); }

else { log.Debug("value assignment is OK"); }

log.Info("Exiting SetRepositoryValue()");

}

We're done with coding and configuration. log4net outputs are shown below.

log4netDemoDemoLogs.log :

2013-03-26 15:08:12,279 [12] DEBUG Log4NetDemo.Service.ServiceBase .ctor - ServiceBase Constructor Call

2013-03-26 15:08:12,335 [12] INFO Log4NetDemo.Service.Service1 SetValue - Entering SetValue(), value = 5

2013-03-26 15:08:12,339 [12] DEBUG Log4NetDemo.Service.Service1 SetValue - Business initialization is OK

2013-03-26 15:08:12,340 [12] INFO Log4NetDemo.Business.Business1 SetBusinessValue - Entering SetBusinessValue(), value = 5

2013-03-26 15:08:12,347 [12] DEBUG Log4NetDemo.Business.Business1 SetBusinessValue - Repository1 initialization is OK

2013-03-26 15:08:12,348 [12] INFO Log4NetDemo.Repository.Repository1 SetRepositoryValue - Entering SetRepositoryValue(): value = 5

2013-03-26 15:08:12,352 [12] INFO DBLogger SetRepositoryValue - Setting Repository Value: 5

2013-03-26 15:08:12,374 [12] INFO Log4NetDemo.Repository.Repository1 SetRepositoryValue - Exiting SetRepositoryValue()

2013-03-26 15:08:12,374 [12] INFO Log4NetDemo.Business.Business1 SetBusinessValue - Exiting SetBusinessValue()

2013-03-26 15:08:12,374 [12] INFO Log4NetDemo.Service.Service1 SetValue - Exiting SetValue()

2013-03-26 15:08:15,386 [16] DEBUG Log4NetDemo.Service.ServiceBase .ctor - ServiceBase Constructor Call

2013-03-26 15:08:15,397 [16] INFO Log4NetDemo.Service.Service1 GetValue - Entering GetValue()

2013-03-26 15:08:15,397 [16] DEBUG Log4NetDemo.Service.Service1 GetValue - Business initialization is OK

2013-03-26 15:08:15,397 [16] INFO Log4NetDemo.Business.Business1 GetBusinessValue - Entering GetBusinessValue()

2013-03-26 15:08:15,398 [16] DEBUG Log4NetDemo.Business.Business1 GetBusinessValue - Repository initialization is OK

2013-03-26 15:08:15,398 [16] INFO Log4NetDemo.Repository.Repository1 GetRepositoryValue - Entering GetRepositoryValue()

2013-03-26 15:08:15,398 [16] INFO Log4NetDemo.Repository.Repository1 GetRepositoryValue - Exiting GetRepositoryValue()

2013-03-26 15:08:15,398 [16] INFO Log4NetDemo.Business.Business1 GetBusinessValue - Exiting GetBusinessValue()

2013-03-26 15:08:15,399 [16] INFO Log4NetDemo.Service.Service1 GetValue - Exiting GetValue()

Log Table in DB :

Debugging log4net

A wrong configuration might stop log4net working. As you suggest, it is quite frustrating. In such a case, that would be a nice idea to see the logs of the tool. Well, it sounds kinda weird : "logging the logger", but believe me you might need that!!

In order to store log4net logs in a file, add this configuration to the web.config :

<system.diagnostics>

<add

name="textWriterTraceListener"

type="System.Diagnostics.TextWriterTraceListener"

initializeData="D:\log4net\diagnose\log4netdemo.txt" />

</listeners>

</trace>

</system.diagnostics>

Orko's Blog

Wednesday, March 27, 2013

Sample log4net Implementation in a WCF .NET Application

Why do I need logging?

log4net

Sample log4net Implementation for an N-Tier WCF Application

Debugging log4net

About Me