Externalising dependencies with Dependency Injection in .NET part 5: logging with log4net

Introduction

In the previous post we looked at how to hide the concrete implementation of the logging technology behind an abstraction. In fact we reached the original goal of showing how to rid the code of logging logic or at least how to make the code less dependent on it.

In the posts on caching and configuration we also looked at some real implementations of the abstractions that you can readily use in your project. However, with logging we only provided a simple Console based logging which is far from realistic in any non-trivial application. Therefore I’ve decided to extend the discussion on logging with a real powerhouse: log4net by Apache.

Log4net is a well-established, general purpose and widely used logging framework for .NET. You can set it up to send logging messages to multiple targets: console, file, database, a web service etc. In this post we’ll look at how to log to a file using log4net.

In a real-life large web-based application you would likely log to at least 2 sources: a file or a database and another, more advanced tool which helps you search among the messages in an efficient way. An example of such a tool is GrayLog, a web-based application where you can set up your channels and make very quick and efficient searches to track your messages.

The primary source of investigation in case of exception tracking will be this advanced tool. However, as in the case of GrayLog it may be down in which case the log messages are lost. As a backup you can then read the log messages from the log file. As mentioned above, we’ll be looking into file-based logging but if you’re looking for a more professional tool then I can recommend GrayLog.

NB: I’m not going to go through log4net specific details too much so be prepared to do your own search in some areas. A full description and demo of log4net would deserve its own series which is out of bounds in this case. However, the goal is to provide code that you can readily use in your project without much modification.

We’ll build upon the CommonInfrastructureDemo project we’ve been working with so far so have it open in Visual Studio.

Some basics

Let’s go through some preparations first. The log4net library is available through NuGet. Add the following NuGet package to the Infrastructure.Common project:

log4net NuGet

By the time you read this post the version may be higher but hopefully it won’t have any breaking changes.

As mentioned above, log4net can be configured to send the log messages to a variety of sources. Log4net will have one or more so-called appenders that will “append” the message to the defined source. Log4net can be configured in code or via a separate configuration file. The advantage of a configuration file is that you can modify the values on the deploy server without re-deploying the application. There are numerous examples on the internet showing snippets of log4net configurations. A very good starting point is the documentation on the log4net homepage available here.

In our case we’ll go for the RollingFileAppender. If the log file exceeds a certain limit then the oldest messages are erased to make room for the new ones. Add an Application Configuration File file called log4net.config to the root of the Console app, i.e. to the same level as the app.config file. Erase any default content in log4net.config and instead add the following XML content:

<?xml version="1.0"?>
<log4net>
	<appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
		<file value="log.xml"/>
		<threshold value="INFO" />
		<appendToFile value="true" />
		<rollingStyle value="Size" />
		<maxSizeRollBackups value="30" />
		<maximumFileSize value="30MB" />
		<staticLogFileName value="true" />
		<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
		<layout type="log4net.Layout.XMLLayout" />
	</appender>

	<root>
		<level value="ALL" />
		<!-- Value of priority may be ALL, DEBUG, INFO, WARN, ERROR, FATAL, OFF -->
		<appender-ref ref="RollingFileAppender"/>
	</root>
</log4net>

You can find the full documentation of the rolling file appender here and here. The main thing to note that we want to log to a file called log.xml. In Solution Explorer right-click log4net.config and select Properties. Locate the “Copy to Output Directory” in the Properties window and select “Copy always”. This will put the config file to the bin folder when the application is compiled.

We’ll need to store the name of the log4net config file name in the application configuration file which we added in the post on configuration referred to above. Add the following app setting to app.config:

<add key="Log4NetSettingsFile" value="log4net.config"/>

The log4net implementation of ILoggingService will therefore need an IConfigurationRepository we saw before. It’s good that we have an implementation of IConfigurationRepository that reads from the app.config file so we’ll be able to use it.

However, we need something more. Whenever you’re trying to track down what exactly went wrong in the application based on a series of log messages you’ll need all sorts of contextual information: the user, the session, the user agent, the referrer, the exact version of the browser, the requested URL etc. Add a new folder to Infrastructure.Common called ContextProvider and insert an interface called IContextService into it:

public interface IContextService
{
	string GetContextualFullFilePath(string fileName);
	string GetUserName();
	ContextProperties GetContextProperties();
}

GetContextualFullFilePath will help us find the full path to a physical file after the deployment of the application. In our case we want to be able to find log4net.config. GetUserName is probably self-explanatory. All other context properties will be stored in the ContextProperties object. Add the following class to the ContextProvider folder:

public class ContextProperties
{
	private string _notAvailable = "N/A";

	public ContextProperties()
	{
		UserAgent = _notAvailable;
		RemoteHost = _notAvailable;
		Path = _notAvailable;
		Query = _notAvailable;
		Referrer = _notAvailable;
		RequestId = _notAvailable;
		SessionId = _notAvailable;
	}

	public string UserAgent { get; set; }
	public string RemoteHost { get; set; }
	public string Path { get; set; }
	public string Query { get; set; }
	public string Referrer { get; set; }
	public string RequestId { get; set; }
	public string SessionId { get; set; }
	public string Method { get; set; }
}

In a web-based application with a valid HttpContext object we can have the following implementation. Add the following class to the ContextProvider folder:

public class HttpContextService : IContextService
{
	public HttpContextService()
	{
		if (HttpContext.Current == null)
		{
			throw new ArgumentException("There's no available Http context.");
		}
	}

	public string GetContextualFullFilePath(string fileName)
	{
		return HttpContext.Current.Server.MapPath(string.Concat("~/", fileName));
	}

	public string GetUserName()
	{
		string userName = "<null>";
		try
		{
			if (HttpContext.Current != null && HttpContext.Current.User != null)
			{
				userName = (HttpContext.Current.User.Identity.IsAuthenticated
								? HttpContext.Current.User.Identity.Name
								: "<null>");
			}
		}
		catch
		{
		}
		return userName;
	}

	public ContextProperties GetContextProperties()
	{
		ContextProperties props = new ContextProperties();
		if (HttpContext.Current != null)
		{
			HttpRequest request = null;
			try
			{
				request = HttpContext.Current.Request;
			}
			catch (HttpException)
			{
			}
         		if (request != null)
			{
				props.UserAgent = request.Browser == null ? "" : request.Browser.Browser;
				props.RemoteHost = request.ServerVariables == null ? "" : request.ServerVariables["REMOTE_HOST"];
				props.Path = request.Url == null ? "" : request.Url.AbsolutePath;
				props.Query = request.Url == null ? "" : request.Url.Query;
				props.Referrer = request.UrlReferrer == null ? "" : request.UrlReferrer.ToString();
				props.Method = request.HttpMethod;
			}

			IDictionary items = HttpContext.Current.Items;
			if (items != null)
			{
				var requestId = items["RequestId"];
				if (requestId != null)
				{
					props.RequestId = items["RequestId"].ToString();
				}
			}

			var session = HttpContext.Current.Session;
			if (session != null)
			{
				var sessionId = session["SessionId"];
				if (sessionId != null)
				{
					props.SessionId = session["SessionId"].ToString();
				}
			}
		}

		return props;
	}
}

Most of this code is about extracting various data from the HTTP request/context.

In a non-HTTP based application we’ll go for a simpler implementation. Add a class called ThreadContextService to the ContextProvider folder:

public class ThreadContextService : IContextService
{
	public string GetContextualFullFilePath(string fileName)
	{
		string dir = Directory.GetCurrentDirectory();
		FileInfo resourceFileInfo = new FileInfo(Path.Combine(dir, fileName));
		return resourceFileInfo.FullName;
	}

	public string GetUserName()
	{
		string userName = "<null>";
		try
		{
			if (Thread.CurrentPrincipal != null)
			{
				userName = (Thread.CurrentPrincipal.Identity.IsAuthenticated
								? Thread.CurrentPrincipal.Identity.Name
								: "<null>");
			}
		}
		catch
		{
		}
		return userName;
	}

	public ContextProperties GetContextProperties()
	{
		return new ContextProperties();
	}
}

Now we have all the ingredients for the log4net implementation if ILoggingService. Add the following class called Log4NetLoggingService to the Logging folder:

public class Log4NetLoggingService : ILoggingService
{
	private readonly IConfigurationRepository _configurationRepository;
	private readonly IContextService _contextService;
	private string _log4netConfigFileName;

	public Log4NetLoggingService(IConfigurationRepository configurationRepository, IContextService contextService)
	{
		if (configurationRepository == null) throw new ArgumentNullException("ConfigurationRepository");
		if (contextService == null) throw new ArgumentNullException("ContextService");
		_configurationRepository = configurationRepository;
		_contextService = contextService;
		_log4netConfigFileName = _configurationRepository.GetConfigurationValue<string>("Log4NetSettingsFile");
		if (string.IsNullOrEmpty(_log4netConfigFileName))
		{
			throw new ApplicationException("Log4net settings file missing from the configuration source.");
		}
		SetupLogger();
	}

	private void SetupLogger()
	{
		FileInfo log4netSettingsFileInfo = new FileInfo(_contextService.GetContextualFullFilePath(_log4netConfigFileName));
		if (!log4netSettingsFileInfo.Exists)
		{
			throw new ApplicationException(string.Concat("Log4net settings file ", _log4netConfigFileName, " not found."));
		}
		log4net.Config.XmlConfigurator
			.ConfigureAndWatch(log4netSettingsFileInfo);
	}

	public void LogInfo(object logSource, string message, Exception exception = null)
	{
		LogMessageWithProperties(logSource, message, Level.Info, exception);
	}

	public void LogWarning(object logSource, string message, Exception exception = null)
	{
		LogMessageWithProperties(logSource, message, Level.Warn, exception);
	}

	public void LogError(object logSource, string message, Exception exception = null)
	{
		LogMessageWithProperties(logSource, message, Level.Error, exception);
	}

	public void LogFatal(object logSource, string message, Exception exception = null)
	{
		LogMessageWithProperties(logSource, message, Level.Fatal, exception);
	}

	private void LogMessageWithProperties(object logSource, string message, Level level, Exception exception)
	{
		var logger = LogManager.GetLogger(logSource.GetType());
			
		var loggingEvent = new LoggingEvent(logSource.GetType(), logger.Logger.Repository, logger.Logger.Name, level, message, null);
		AddProperties(logSource, exception, loggingEvent);
		try
		{
			logger.Logger.Log(loggingEvent);				
		}
		catch (AggregateException ae)
		{
			ae.Handle(x => { return true; });
		}
		catch (Exception) { }
	}

	private string GetUserName()
	{
		return _contextService.GetUserName();
	}

	private void AddProperties(object logSource, Exception exception, LoggingEvent loggingEvent)
	{
		loggingEvent.Properties["UserName"] = GetUserName();
		try
		{
			ContextProperties contextProperties = _contextService.GetContextProperties();
			if (contextProperties != null)
			{
				try
				{						
					loggingEvent.Properties["UserAgent"] = contextProperties.UserAgent;
					loggingEvent.Properties["RemoteHost"] = contextProperties.RemoteHost;
					loggingEvent.Properties["Path"] = contextProperties.Path;
					loggingEvent.Properties["Query"] = contextProperties.Query;
					loggingEvent.Properties["RefererUrl"] = contextProperties.Referrer;
					loggingEvent.Properties["RequestId"] = contextProperties.RequestId;
					loggingEvent.Properties["SessionId"] = contextProperties.SessionId;
				}
				catch (Exception)
				{
				}
			}
				
			loggingEvent.Properties["ExceptionType"] = exception == null ? "" : exception.GetType().ToString();
			loggingEvent.Properties["ExceptionMessage"] = exception == null ? "" : exception.Message;
			loggingEvent.Properties["ExceptionStackTrace"] = exception == null ? "" : exception.StackTrace;
			loggingEvent.Properties["LogSource"] = logSource.GetType().ToString();
		}
		catch (Exception ex)
		{
			var type = typeof(Log4NetLoggingService);
			var logger = LogManager.GetLogger(type);
			logger.Logger.Log(type, Level.Fatal, "Exception when extracting properties: " + ex.Message, ex);
		}
	}		
}

We inject two dependencies by way of constructor injection: IConfigurationRepository and IContextService. IConfigurationRepository will help us locate the name of the log4net configuration file. IContextService will provide contextual data to the log message. Log4net is set up in SetupLogger(). We check for the existence of the config file. We then call log4net.Config.XmlConfigurator.ConfigureAndWatch to let log4net read the configuration settings from an XML file and watch for any changes.

The implemented LogX messages all call upon LogMessageWithProperties where we simply wrap the log message in a LoggingEvent object along with all contextual data.

Originally we had the below code to instantiate a logged and cached ProductService to log to the console:

IProductService productService = new ProductService(new ProductRepository(), new ConfigFileConfigurationRepository());
IProductService cachedProductService = new CachedProductService(productService, new SystemRuntimeCacheStorage());
IProductService loggedCachedProductService = new LoggedProductService(cachedProductService, new ConsoleLoggingService());

We can easily change the logging mechanism by simply injecting the log4net implementation of ILoggingService into LoggedProductService:

IConfigurationRepository configurationRepository = new ConfigFileConfigurationRepository();
IProductService productService = new ProductService(new ProductRepository(), configurationRepository);
IProductService cachedProductService = new CachedProductService(productService, new SystemRuntimeCacheStorage());
ILoggingService loggingService = new Log4NetLoggingService(configurationRepository, new ThreadContextService());
IProductService loggedCachedProductService = new LoggedProductService(cachedProductService, loggingService);

Run Program.cs and if all went well then you’ll have a new file called log.xml in the …MyCompany.ProductConsole/bin/Debug folder with some XML entries. Here comes an excerpt:

<log4net:event logger="MyCompany.ProductConsole.Services.LoggedProductService" timestamp="2014-08-23T22:44:52.7591938+02:00" level="INFO" thread="9" domain="MyCompany.ProductConsole.vshost.exe" username="andras.nemes"><log4net:message>Starting GetProduct method</log4net:message><log4net:properties><log4net:data name="log4net:HostName" value="andras1" /><log4net:data name="Path" value="N/A" /><log4net:data name="SessionId" value="N/A" /><log4net:data name="log4net:UserName" value="andras.nemes" /><log4net:data name="Query" value="N/A" /><log4net:data name="ExceptionMessage" value="" /><log4net:data name="UserName" value="&lt;null&gt;" /><log4net:data name="RefererUrl" value="N/A" /><log4net:data name="LogSource" value="MyCompany.ProductConsole.Services.LoggedProductService" /><log4net:data name="RemoteHost" value="N/A" /><log4net:data name="ExceptionStackTrace" value="" /><log4net:data name="UserAgent" value="N/A" /><log4net:data name="ExceptionType" value="" /><log4net:data name="RequestId" value="N/A" /><log4net:data name="log4net:Identity" value="" /></log4net:properties></log4net:event>

So it took some time to implement the log4net version of ILoggingService but to switch from the console-based implementation was a breeze.

However, you may still see one log message logged to the console. That’s from the code line in ProductService.GetProduct:

LogProviderContext.Current.LogInfo(this, "Log message from the contextual log provider");

…where LogProviderContext returns a ConsoleLoggingService by default. However, it also allows us to set the implementation of ILoggingService. Insert the following code in Main…

LogProviderContext.Current = loggingService;

…just below…

ILoggingService loggingService = new Log4NetLoggingService(configurationRepository, new ThreadContextService());

Then you’ll see that even the previously mentioned log message ends up in log.xml:

<log4net:event logger="MyCompany.ProductConsole.Services.ProductService" timestamp="2014-08-23T22:56:19.411468+02:00" level="INFO" thread="8" domain="MyCompany.ProductConsole.vshost.exe" username="andras.nemes"><log4net:message>Log message from the contextual log provider</log4net:message><log4net:properties><log4net:data name="log4net:HostName" value="andras1" /><log4net:data name="Path" value="N/A" /><log4net:data name="SessionId" value="N/A" /><log4net:data name="log4net:UserName" value="andras.nemes" /><log4net:data name="Query" value="N/A" /><log4net:data name="ExceptionMessage" value="" /><log4net:data name="UserName" value="&lt;null&gt;" /><log4net:data name="RefererUrl" value="N/A" /><log4net:data name="LogSource" value="MyCompany.ProductConsole.Services.ProductService" /><log4net:data name="RemoteHost" value="N/A" /><log4net:data name="ExceptionStackTrace" value="" /><log4net:data name="UserAgent" value="N/A" /><log4net:data name="ExceptionType" value="" /><log4net:data name="RequestId" value="N/A" /><log4net:data name="log4net:Identity" value="" /></log4net:properties></log4net:event>

So that’s it about logging. We’ll continue with the file system in the next part.

View the list of posts on Architecture and Patterns here.

Advertisements

About Andras Nemes
I'm a .NET/Java developer living and working in Stockholm, Sweden.

6 Responses to Externalising dependencies with Dependency Injection in .NET part 5: logging with log4net

  1. Bob Taylor says:

    Andras, in your post ‘…DIP Part 2, DI patterns’ you discuss ambient context. You state that ‘A disadvantage with the ambient context approach is that the consuming class carries an implicit dependency’ e.g. ProductService.TestTime(). This implicit dependency (the ambient context) carried by the consuming class violates the principle of Intention-Revealing Interfaces. So far so good. However, in this post, you demonstrate two implementations of the IContextService interface that use the ambient context and produce an implicit dependency. The HttpContextService class uses the HttpContext ambient context and the ThreadContextService class uses the System.Threading.Thread ambient context. Isn’t this a violation of the principle of Intention-Revealing Interfaces?

    • Andras Nemes says:

      Hi Bob, thanks for your comment.

      I would say no, they don’t violate that rule. Both implementations use an ambient context but the implementations clearly state that in their names: HttpContextService and ThreadContextService. They imply to the caller that they will use these contexts actively.

      Compare this with a hidden call to a logging service within a method called “GetCustomer(int customerId)”. There’s absolutely nothing in this declaration indicating that there’s logging going on within this function. If, however, GetCustomer accepts an integer and an ILogger then it’s fine. Also, if GetCustomer(int customerId) is located within a class called CustomerService whose constructor accepts an ILogger then that may be acceptable, I’m not quite sure.

      //Andras

  2. Bob Taylor says:

    Hi Andras, thanks for your reply. I really appreciate that you take the time to respond to comments. BTW, I think your posts are very informative. Ok, I can see that both implementations don’t violate the rule because the use of an ambient context is clearly stated in their names. What happened is that I got mixed up and the question I asked was completely wrong. It was not what I intended. I apologize.

    The comment I meant to make lies in the relationship between IRI – Intention-Revealing Interfaces and the ‘disadvantage with the ambient context approach is that the consuming class carries an implicit dependency’. According to Eric Evans the principle of Intention-Revealing Interfaces states that you should ‘Name classes and operations to describe their effect and purpose, without reference to the means by which they do what they promise. This relieves the client developer of the need to understand the internals’. You summed up the principle yourself stating ‘An API should communicate ‘what’ it does by its public interface alone’. If I understand the principle correctly it basically states that a class/API with its public methods/operations/properties, which constitutes its ‘public interface’, should clearly communicate its ‘purpose’ or ‘what’ it does. It is universally understood however, that it (the public interface) does not reveal how or reference the means by which it accomplishes its purpose. The ‘how’ is an implementation detail; this is encapsulation. continued…

    • Bob Taylor says:

      … A ‘hidden call to a logging service within a method’ may violate SRP, but not IRI. What if a method requires logging, security, configuration and error handling (ignore the SRP violation). By your definition we would have two options to ensure IRI by revealing dependencies. The first option is the method name: e.g. GetCustomerAndLogAndPerformSecurityCheckAndUseConfigurationInfoAndHandleErrors(int customerId). The second option is the method signature: e.g. GetCustomer(int customerId, ILogger logger, ISecurity security, IConfiguration config, IErrorHandler errHandler). I think you would agree that neither option reflects the ubiquitous language of the domain and does not support IRI the way the author intended.

      The principle of Intention-Revealing Interfaces is orthogonal to DIP or IoC. It does not refer to dependencies at all, either explicit or implicit. It is not a principle of ‘louse coupling’ and it does not state that dependencies must be ‘revealed’ in order to convey ‘intention’. The existence of a dependency (including the ambient context), whether it is ‘concealed’ or not, does not violate the principle of Intention-Revealing Interfaces. This is the conclusion I have come to based on my understanding of the principle. I want to understand this correctly so if I have misunderstood something please let me know.

      Sincerely, Bob

      • Andras Nemes says:

        Hi Bob,

        I don’t know if you have misunderstood anything, I think we’ve just come to somewhat different conclusions. Maybe Eric Evans could help us out, you give very reasonable arguments. I’m more strict with the interpretation of the IRI principle than you are I guess. I don’t take the word “interface” in IRI as the programmatic interface, but any public API signature whether it’s a concrete implementation or not. In my mind a public API should communicate its purpose by its publicly visible elements alone. Of course it’s stupid to name methods like ‘GetCustomerAndLogAndPerformSecurityCheckAndUseConfigurationInfoAndHandleErrors’. However, a developer looking through the public parts of a class should be able to see what dependencies it needs in order to carry out its job without having to go through the internal implementations. A hidden ambient context does the exact opposite.

        //Andras

  3. Pingback: Architecture and patterns | Michael's Excerpts

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

ultimatemindsettoday

A great WordPress.com site

Elliot Balynn's Blog

A directory of wonderful thoughts

Robin Sedlaczek's Blog

Developer on Microsoft Technologies

HarsH ReaLiTy

A Good Blog is Hard to Find

Softwarearchitektur in der Praxis

Wissenswertes zu Webentwicklung, Domain-Driven Design und Microservices

the software architecture

thoughts, ideas, diagrams,enterprise code, design pattern , solution designs

Technology Talks

on Microsoft technologies, Web, Android and others

Software Engineering

Web development

Disparate Opinions

Various tidbits

chsakell's Blog

Anything around ASP.NET MVC,WEB API, WCF, Entity Framework & AngularJS

Cyber Matters

Bite-size insight on Cyber Security for the not too technical.

Guru N Guns's

OneSolution To dOTnET.

Johnny Zraiby

Measuring programming progress by lines of code is like measuring aircraft building progress by weight.

%d bloggers like this: