log4net output not appearing in some tests - how work around?

Question

I have 100's of unit tests. Most of my logging works fine (i.e., appears in the ReSharper and VS test runner Output windows). However, very oddly, some tests persistently fail to write to the Output Window using log4net (apparently due to 0 appenders). I tracked it down to a private logger field in a referenced class.

Why does the presence of a private Logger field in one class (e.g., FooA) break logging in a different test class (e.g., FooOtherTest)? Is this just a bug in log4net? What is the mechanism of action? (so I can avoid it or workaround it...since it is really hard to track down in code when it occurs due to the levels of indirection).

The 2 files are in 2 different projects (a class library project and a test project). The test project has a log4net.config file w/ Build Action = Content and Copy to Output Directory = Copy Always.

VS2017 Enterprise Version 15.7.4, log4net 2.0.8.0, C# 4.7.1

Here is an illustration that it happens in Visual Studio Test Explorer as well.

Here is the code:

 using log4net;

 namespace FooBug
 {
    public static class FooA
    {
        // toggle to see symptom come and go (excluded = works fine, included = logging in test class fails)
        //private static readonly ILog Logger = LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);
        public static readonly int fooA = 4;
    }
}

using System;
using FooBug;
using log4net;
using Microsoft.VisualStudio.TestTools.UnitTesting;

namespace OtherTest
{
    [TestClass]
    public class FooOtherTest
    {
        private static readonly ILog Logger = LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

        private static readonly int fooA = FooA.fooA;

        [TestMethod]
        public void Test0()
        {
            Console.WriteLine(@"sanity check to console");
            Logger.Debug("SUCCESS - the logging works right now");

            ConsoleWriteAppenders();
        }

        public static void ConsoleWriteAppenders()
        {
            var appenders = LogManager.GetRepository().GetAppenders();
            Console.WriteLine("appenders.Length = " + appenders.Length);

            foreach (var appender in appenders)
            {
                Console.WriteLine(appender.Name);
            }
        }

    }
}

You want your unit tests to be as simple as possible. For this reason use a standard logging method like `Debug.WriteLine` or `Trace.TraceInformation`. Otherwise by introducing dependencies in the test increases the amount of testing the actual test requires. The fact you are having issues proves my point. (not to mention incorrect setup of Log4Net strips out output to win32's `OutputDebugSting` the output window depends on!). Typical use cases for Log4net dont overlap with unit tests — , Jul 06 '18 at 00:22

score 1 · Accepted Answer · answered Jul 06 '18 at 11:50

Is this just a bug in log4net?

If what I think is happening is correct, then it is documented behaviour.

See https://logging.apache.org/log4net/release/faq.html#first-log

If you are configuring log4net by specifying assembly level attributes on your assembly then the configuration will be loaded once the first call to the LogManager.GetLogger is made. It is necessary that the first call to LogManager.GetLogger made during the process (or AppDomain) is made from the assembly that has the configuration attributes. Log4net will look only once and only on the first calling assembly for the configuration attributes.

I would suspect this is because FooOtherTest depends on FooA and so that dll will be loaded first and hence the the logger will be initialised from that dll and does not find the config which is in the test project.

You need to try to make sure the first logging takes place in an assembly that has the correct attributes and where the config file can be found.

See also Initialize log4Net as early as possible with NUnit (It's about NUnit, but most test systems have something similar)

Agreed, that sounds like the problem. I assumed the logger field appearing before the class-library-referencing field would cause that to load first. My app project typically has the log4net.config for the app. I then typically have links to this log4net.config in each of my unit test projects, but NOT the other class library projects since they are expected to use the app log4net.config. The thinking is that the app is an entry point and so are the test projects. Perhaps I need to start linking to the log4net.config in the class libraries as well. — dthal, Jul 06 '18 at 17:46
Your hypothesis is confirmed. Static fields are initialized in a diff order than I expected. It's a function of usage order, not declaration order ( https://stackoverflow.com/a/4995709/8352092). So FooOtherTest.Logger (test project w/ log4net config) is NOT initialized before FooA.Logger (class library w/o config). The workaround is to go ahead include log4net.config in class library projects as well (even though they do not have an application or test entry point). — dthal, Jul 09 '18 at 17:40

score 0 · Answer 2 · answered Jul 09 '18 at 17:47

@sgmoore Is correct. The subsequent workaround I chose was to begin including log4net.config in all class library projects (also need XmlConfigurator line in AssemblyInfo.cs), even though the class library projects do not have application or test entry points.

log4net output not appearing in some tests - how work around?

2 Answers2