Log4net not working with NUnit

[Charlie Poole]

[Bug now tracked at https://github.com/nunit/nunit-framework/issues/6]

Problem: Using log4net with newer versions of nunit means that no
log file is created.

Demonstration follows.

I created the solution in VS 2008.
The OS is Windows XP.
I tested using both the nunit GUI and console.
I compared Nunit 2.2.5 with 2.5.5 (I suspect 2.5.0 will fail as well.)
The solution is created as a console app.

When the app is run as a console application a Log file is produced.
When the app is run using 2.2.5 a Log file is produced.
When the app is run using 2.5.5 no Log file is produced.

There are two files in the solution: Log.config and Program.cs

Following comes from a file name "Log.config"

----------------------------------------------
<?xml version="1.0" encoding="utf-8" ?>
<log4net debug="false">

  <appender name="DefaultLogFile" type="log4net.Appender.RollingFileAppender">
      <file value=".\Log" />
      <appendToFile value="false" />
      <staticLogFileName value="false" />
      <rollingStyle value="Date" />
      <datePattern value="'.'yyyyMMdd'.log'" />
      <layout type="log4net.Layout.PatternLayout">

        <conversionPattern value="%utcdate{ABSOLUTE} %-5level %message%newline" />

      </layout>
  </appender>

  <root>
    <level value="All" />
    <appender-ref ref="DefaultLogFile" />
  </root>
</log4net>
-----------------------------------------------------

Following is Program.cs

-----------------------------------------------------
using System;
using System.Reflection;
using NUnit.Framework;

[assembly: log4net.Config.XmlConfiguratorAttribute(ConfigFile = "Log.config", Watch = true)]

namespace TestNunitLog4net
{
[TestFixture]
public class Program
{
  private static readonly log4net.ILog log
        = log4net.LogManager.GetLogger(
            MethodBase.GetCurrentMethod().DeclaringType);

  // Test scenarios
  // Test 1: Works - log show up (gui and console)
  // log4net: 1.2.10.0
  // Nunit: 2.2.5.0

  // Test 2: Fails - no log file (gui and console)
  // log4net: 1.2.10.0
  // Nunit: 2.5.5.10112

  // Following has no impact.
  // It exists just so we can see it in log.
  private readonly String exeType;

  static void Main()
  {
    Program p = new Program("Exe");
    p.TestLog();
  }

  private Program(String stype)
  {
    this.exeType = stype;
  }

  public Program()
  {
    this.exeType = "Nunit";
  }

  [Test]
  public void TestLog()
  {
    log.Debug(exeType + ": First line");
    log.Debug(exeType + ": Second line");
  }

} // End of class
} // End of namespace
---------------------------------------------------------------

[Charlie Poole (charlie.poole)]

With current versions of NUnit, you can make your example work by adding a line like this to the public constructor...
      log4net.Config.XmlConfigurator.Configure(new System.IO.FileInfo("Log.config"));

I have confirmed that the program works without this change under NUnit 2.2.10. It does not work under 2.4.8 or 2.5.7. Whatever changed, it was a long time back. We'll work this problem as time is available, but it's a low priority.

BTW, I like your trick for running the same program under NUnit and standalone.

Charlie

[Rover (infoseeker002)]

Hi Charlie,

I do not believe that it is a bug at all. I have provided two solutions in my blog post
http://do-the-right-things.blogspot.com/2010/11/log4net-configuration-issue-when-using.html

In short, it is because NUnit contains code in NUnit.Core.Log4NetCapture.StartCapture() that causes log4net to construct a default repository without finding the user's specified config file. Full technical disclosure is found on my blog post.

The way to over come this is to put a key="log4net.Config" in the <appSettings> in the NUnit project's config file and in the value specify the log4net config file. With this simple specifiication, NUnit 2.5.7 will work just fine.

Rover.

[Charlie Poole (charlie.poole)]

Interesting blog post - I'll have to read it more carefully to see if there is
any way that we can make the workaround unnecessary. If not, this
will just be a "won't fix" for NUnit 2.x.

There seems to be one misunderstanding of what NUnit is doing in your
post. You write

"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."

In fact, NUnit does not use log4net for logging. (One exception,
pnunit, which was written by
a third party, does use it.) Where you see NUnit creating loggers
using a static syntax similar
to that of log4net, it's actually creating loggers for its own
internal trace facility.

With NUnit 3.0, we'll revisit this issue and may provide separate
addins for capturing output
from various logging systems.

Charlie

On Sat, Nov 13, 2010 at 4:24 AM, Rover <email address hidden> wrote:
> Hi Charlie,
>
> I do not believe that it is a bug at all. I have provided two solutions in my blog post
> http://do-the-right-things.blogspot.com/2010/11/log4net-configuration-issue-when-using.html
>
> In short, it is because NUnit contains code in
> NUnit.Core.Log4NetCapture.StartCapture() that causes log4net to
> construct a default repository without finding the user's specified
> config file. Full technical disclosure is found on my blog post.
>
> The way to over come this is to put a key="log4net.Config" in the
> <appSettings> in the NUnit project's config file and in the value
> specify the log4net config file. With this simple specifiication, NUnit
> 2.5.7 will work just fine.
>
> Rover.
>
> --
> Log4net not working with NUnit
> https://bugs.launchpad.net/bugs/605034
> You received this bug notification because you are a member of NUnit
> Developers, which is subscribed to NUnit V2.
>

[Charlie Poole (charlie.poole)]

On the question of when this problem was introduced, the code that causes a default repository to be created by log4net was introduced in NUnit 2.4.7. It's a reflection call to the Configure method on our own appender.

Two approaches might eliminate the need for the workaround:

1. Find a way to force the initialization early (programmatically that is).

2. Find a way to be notified when the log4net initialization has taken place.

A completely different approach would be to require the user to specify the nunit appender
in the log4net configuration in order to see the output in the gui. This does less for the
user, but isn't much different from what you're doing anyway in order to use log4net.

[Charlie Poole (charlie.poole)]

Added nunit 3.0 as an affected project. For 3.0, we will need to think carefully about how to make this work better.

[Charlie Poole (charlie.poole)]

A partial fix is in for NUnit 2.6. We'll think about further improvements for 3.0.

For 2.6, the log capture no longer takes place when using the console runner. Since the console runner doesn't do anything with the captured output, it was really never needed anyway. Now we only capture log output if the package contains a setting indicating that it should be captured. Only the Gui creates that setting. For good measure, I did the same with trace output.

[Charlie Poole (charlie.poole)]

Moved issue to https://github.com/nunit/nunit-gui/issues/2