Log4Net configuration issue when using with NUnit - Solutions & Explanation

Log4Net is a widely used logging framework and an application has to configure it in order for your instructions, such as where to log your message to, what to ignore, etc, are carried out. However, there are several quirks that one has to be aware, particularly when using it with NUnit. This post uses NUnit version 2.5.7 and log4net version 1.2.10 and hence the comments below are relevant to this version combination.

However, when used in NUnit, report has been filed that it does not generate any log file. In other word, the combination fails to find the required configuration file. The report accused NUnit being the culprit but I can assure readers that it is not entirely. This triggers a number of unnecessary work around.

In this post I will give you a number of solutions first and I will go into detail explanation of what causes this quirky behavior. It is neither party's fault but exposing an issue with how log4net loads the configuration, which is not a fault either.

If you are not interested in the technical discussion, just skip the second section.

Solutions

Solution 1 - No need to write code

I prefer this solution because it fits perfectly into "The Most Beautiful Code I Never Wrote".

In order to use NUnit with your test assemblies, which may or may not contain log4net logging calls, that call into your deploy assemblies, the ones being tested, containing log4net calls, do the following steps:
1) Create a NUnit project config file which usually is in the same directory as your NUnit project file, if not already present.

2) In the config file define the key (in red):

<configuration>
  <appSettings>
    <add key="log4net.Config" 
   value="E:\Libraries Tests\Log4NetDemo\Unit Tests\SimpleLog4net-UnitTest.config"/>
  </appSettings>
</configuration>

The value of that key defines the log4net configuration file that will be used to initialize the default repository.

That is all to it! Nice and simple.

Now when you run your NUnit, all your log4net calls will follow the instructions specified in that configuration file.

It is recommended to use full path name in specifying the configuration file due to some quirky behavior of System.Uri( String, String ) call. This will be disclosed in the Technical Discussion section.

Solution 2 - Use work around

While work around generally works but not very scalable, particularly when you have a collection of test fixture classes and/or assemblies. You need to ensure no matter which test assemblies are called that the configuration file still is used. Here is the recipe of a better work around:
1) Create a class NUnitLog4NetLogManager which has a method called GetLogger( Type type ) and package that inside an helper assembly:

static public class NUnitLog4NetLogManager {
  public static ILog GetLogger( Type type ) {
    return GetLogger( Assembly.GetCallingAssembly(), type );
  }
  // ...
} 

2) NUnitLog4NetLogManager.GetLogger() will use the given assembly object to attempt to retrieve any custom attribute of type log4net.Config.XmlConfiguratorAttribute type. Once found it will then use it to retrieve the config file and watch state. With these pieces of information it will form the full pathname of the configuration file using AppDomain.CurrentDomain.BaseDirectory, if the config file is not a full path.

It then form the System.IO.FileInfo with which it then calls XmlConfigurator.Configure() or XmlConfigurator.ConfigureAndWatch() to load the configuration into log4net.

3) Once step 2 is completed, it then calls LoggerManager.GetLogger(Assembly, Type) to grab the logger and return it to the caller.

This technique allows user to use familiar way of specifying the preferred configuration file like this:

// AssemblyInfo.cs
[assembly: log4net.Config.XmlConfigurator(ConfigFile="MyTest.config")]

and to create the logger in a TextFixture class like this:

// MySimpleTest.cs
[TestFixture]
public class MySimpleTest {
  static ILog log = NUnitLog4NetLogManager.GetLogger( typeof(MySimpleTest) );
  [Test]
  public void SimpleTest() {
  // ....
  }
} 

This has advantage over the work around in that any class included into this assembly can make use of the familiar syntax to get a logger and in doing so indirectly load up the configuration file.

Technical Discussion

Typically, an assembly can include an assembly-level Log4Net custom attribute, XmlConfiguratorAttribute, to specify the configuration information. When a situation that needs to load up the configuration file, log4net internal logic will look for an instance of this custom attribute in a given assembly for the configuration file, etc. This class is located in src\Config\XmlConfiguratorAttribute.cs.

In theory, each assembly can use this to specify different configuration file. log4net does not process or configure its system until the first reference to create a logger or an appender. But in practice the first logger created determines the configuration file used and subsequent calls to create different loggers will not load the config file specified in that assembly.

There is really no need to have separate configuration files as one can control all loggers in one configuration file.

Bear this piece of information in mind will help to understand the issue at hand.

When NUnit is launched and before running your test assemblies, code inside NUnit causes NUnit.Core.Log4NetCapture.StartCapture() to execute. This is an override of its parent abstract class TextCapture. The result is that it causes a the log4net.Appender.TextWriteAppender to be created.

When this happens, some how it triggers a call to log4net.Config.BasicConfigurator() for this appender. This in turn causes the creation of Logger Repository for the assembly nunit.core, which in turns starts looking for custom attributes for repository.

Since these custom attributes are rarely used and nothing is found, it then look for an instance of custom attribute log4net.Config.ConfiguratorAttribute or log4net.Config.XmlConfiguratorAttribute in nunit.core to configure this default repository. Note that it is not your assembly that is used to create the logger repository; it is nunit.core.

If no such custom attribute is found it will then look for a value for the key. If a value is returned, it will then use it to configure this default repository (see code DefaultRepositorySelector.ConfigureRepository(Assembly, ILoggerRepository) in src\Core\DefaultRepositorySelector.cs). The logic will eventually then call XmlConfigurator.Configure() to load and configure the default repository.

If nothing is found, it will simply leave this default repository with its default initialized state.

After all this is completed, NUnit will begin to execute the first TestFixture class it can find, when that happens, assuming the logger is created in a static object initialization style, NUnit will call into log4net to create a logger identified by the given type or string. log4net will grab the calling assembly to begin creation of the logger.

Instead of looking for the custom attribute that you have injected into the AssemblyInfo.cs file, for example, to specify the log4net config file, log4net now has a default repository and it will no need to go through the motion to locate those custom attributes.

The result causes people to believe NUnit or log4net is responsible for not finding their configuration file. This is because they do not realize NUnit is the culprit that causes the creation of a default repository with default initialization state. It is not that log4net can't find your log4net config file, no matter how convenient you have placed it. It is simply that by then log4net does not need to do that.

log4net will then create a logger and stashes it into the default repository, which happens to have the default initialized state, that your logger will use when call upon. It then returns this logger back to your code.

When you call the logger (ILogger) method to log messages, it has found that it is not initialized and hence it will not generate the expected log file, if you use FileAppender for example leading to the submission of the bug report on NUnit.

In reality, perhaps NUnit in version 2.5.7 happens by accident trips the load once issue of log4net as described above and hence when it comes to your test assembly, it simply ignores your directive placed inside the config file.

Using Solution 1 causes the creation of the default repository to use that file to initialize the default repository thereby ensuring the logger will obey your instructions.

With respect to using my solution 1, I mentioned that there is a quirky issue with System.Uri(Uri, string) that makes me to recommend the use of full path name for the value in the key. The reason is that depending on whether the base uri for file protocol is your current execution directory, that constructor will drop the last component of your base uri if the current directory is not your base uri  when forming the final uri. The following code fragment illustrates the issue

// Current directory in MyTestAssembly is 
String curDir = "C:\A\Test\MyTestAssembly\bin\debug";
Debug.Assert( Environment.CurrentDirector==curDir );
Uri x = new Uri( new Uri("C:\A\Test\MyTestAssembly"), "hello.txt" );
Debug.Assert( x.LocalPath == "C:\A\Test\hello.txt" );

In the log4net, it uses AppDomain.CurrentDomain.BaseDirectory as the base Uri and this may or may not be the current directory and this uncertainty is very hard to tell since log4net does not throw any exception when the config file does not exist. For this reason, it is best just to use a full path name for your configuration file and this causes Uri(Uri, string) to ignore the base uri.

The work around specifies a full path to the custom log4net config file to construct the FileInfo object to XmlConfigurator.Configure(). This is not necessary because at that point in time, your current directory is the target directory of your test assembly and FileInfo() will always use current directory to fully qualify the supplied file name if it is not an absolute path name.

---

[1] "Beautiful Code - Leading Programmers Explain How They Think" Chapter 3 "The Most Beautiful Code I never wrote".