How to troubleshoot the situation where XUnit tests fail with assertion of messages in NLog target under "Run All"

Question

This is my environment:

• Visual Studio 2017
• Project's .NET runtime version is 4.6.2
• XUnit version 2.3.1
• NLog version 4.4.12
• Fluent Assertions 4.19.4

This is the problem:

When I run the tests individually they pass, however when i run time via the "Run All" button in Test Explorer, I get failures and when repeating the running of the subsequent failed tasks, all of them pass eventually. Also want to point out that I am not running the tests in parallel. The nature of the tests are such that the code under test emits log information which eventually ends up in a custom NLog Target. Here is an example program which can be run in order to reproduce the problem.

using FluentAssertions;
using NLog;
using NLog.Common;
using NLog.Config;
using NLog.Targets;
using System;
using System.Collections.Concurrent;
using System.IO;
using Xunit;

namespace LoggingTests
{
    [Target("test-target")]
    public class TestTarget : TargetWithLayout
    {
        public ConcurrentBag<string> Messages = new ConcurrentBag<string>();

        public TestTarget(string name)
        {
            Name = name;
        }

        protected override void Write(LogEventInfo logEvent)
        {
            Messages.Add(Layout.Render(logEvent));
        }
    }

    class Loggable
    {
        private Logger _logger;

        public Loggable()
        {
            _logger = LogManager.GetCurrentClassLogger();
        }

        private void Log(LogLevel level,
                         Exception exception,
                         string message,
                         params object[] parameters)
        {
            LogEventInfo log_event = new LogEventInfo();
            log_event.Level = level;
            log_event.Exception = exception;
            log_event.Message = message;
            log_event.Parameters = parameters;
            log_event.LoggerName = _logger.Name;
            _logger.Log(log_event);
        }

        public void Debug(string message)
        {
            Log(LogLevel.Debug,
                null,
                message,
                null);
        }

        public void Error(string message)
        {
            Log(LogLevel.Error,
                null,
                message,
                null);
        }

        public void Info(string message)
        {
            Log(LogLevel.Info,
                null,
                message,
                null);
        }

        public void Fatal(string message)
        {
            Log(LogLevel.Fatal,
                null,
                message,
                null);
        }
    }

    public class Printer
    {
        public delegate void Print(string message);
        private Print _print_function;

        public Printer(Print print_function)
        {
            _print_function = print_function;
        }

        public void Run(string message_template,
                        int number_of_times)
        {
            for (int i = 0; i < number_of_times; i++)
            {
                _print_function($"{message_template} - {i}");
            }
        }
    }

    public abstract class BaseTest
    {
        protected string _target_name;

        public BaseTest(LogLevel log_level)
        {
            if (LogManager.Configuration == null)
            {
                LogManager.Configuration = new LoggingConfiguration();
                InternalLogger.LogLevel = LogLevel.Debug;
                InternalLogger.LogFile = Path.Combine(Environment.CurrentDirectory,
                                                      "nlog_debug.txt");
            }

            // Register target:
            _target_name = GetType().Name;
            Target.Register<TestTarget>(_target_name);

            // Create Target:
            TestTarget t = new TestTarget(_target_name);
            t.Layout = "${message}";

            // Add Target to configuration:
            LogManager.Configuration.AddTarget(_target_name,
                                               t);

            // Add a logging rule pertaining to the above target:
            LogManager.Configuration.AddRule(log_level,
                                             log_level,
                                             t);

            // Because configuration has been modified programatically, we have to reconfigure all loggers:
            LogManager.ReconfigExistingLoggers();
        }
        protected void AssertTargetContains(string message)
        {
            TestTarget target = (TestTarget)LogManager.Configuration.FindTargetByName(_target_name);
            target.Messages.Should().Contain(message);
        }
    }

    public class TestA : BaseTest
    {
        public TestA() : base(LogLevel.Info)
        {
        }

        [Fact]
        public void SomeTest()
        {
            int number_of_times = 100;
            (new Printer((new Loggable()).Info)).Run(GetType().Name, 
                                                     number_of_times);
            for (int i = 0; i < number_of_times; i++)
            {
                AssertTargetContains($"{GetType().Name} - {i}");
            }
        }
    }

    public class TestB : BaseTest
    {
        public TestB() : base(LogLevel.Debug)
        {
        }

        [Fact]
        public void SomeTest()
        {
            int number_of_times = 100;
            (new Printer((new Loggable()).Debug)).Run(GetType().Name,
                                                     number_of_times);
            for (int i = 0; i < number_of_times; i++)
            {
                AssertTargetContains($"{GetType().Name} - {i}");
            }
        }
    }

    public class TestC : BaseTest
    {
        public TestC() : base(LogLevel.Error)
        {
        }

        [Fact]
        public void SomeTest()
        {
            int number_of_times = 100;
            (new Printer((new Loggable()).Error)).Run(GetType().Name,
                                                     number_of_times);
            for (int i = 0; i < number_of_times; i++)
            {
                AssertTargetContains($"{GetType().Name} - {i}");
            }
        }
    }

    public class TestD : BaseTest
    {
        public TestD() : base(LogLevel.Fatal)
        {
        }

        [Fact]
        public void SomeTest()
        {
            int number_of_times = 100;
            (new Printer((new Loggable()).Fatal)).Run(GetType().Name,
                                                     number_of_times);
            for (int i = 0; i < number_of_times; i++)
            {
                AssertTargetContains($"{GetType().Name} - {i}");
            }
        }
    }
}

The above test code runs better. After some earlier troubleshooting by following the messages, it appeared that I was not calling LogManager.ReconfigExistingLoggers(); since the configurations are being created programatically (in the constructors of the test classes). Here is a note in the source code of LogManager:

/// Loops through all loggers previously returned by GetLogger.
/// and recalculates their target and filter list. Useful after modifying the configuration programmatically
/// to ensure that all loggers have been properly configured.

Afterwards all the tests ran as expected with occasional failures like shown below:

I am wondering now if there is anything more I should be securing in my test setup or is this rather a bug NLog. Any suggestion on how to go about to fix my test setup or, troubleshoot the setup would be most welcome. Thanks in advance.

---

Update

• Changed List<LogData> to ConcurrentBag<LogData>. This however does not change the problem. Problem remains that messages are not arriving into collection in a timely manner.
• Reformulated the problem and replaced previous code sample with an actual example (that can be run to reproduce the problem) + screenshots of the problem.
• Improved tests which run better but occasionally fail due to exceptions coming from NLog itself (added screenshot).

Answer 1

The problem with above issue happens to be with XUnit Runner in VisualStudio. Eventhough i had 'DO NOT RUN TESTS IN PARALLEL' disabled, the tests were running in parallel somehow. @rolf-kristensen pointed in another NLog issue (Ref: https://github.com/NLog/NLog/issues/2525) that he had added the following:

[assembly: Xunit.CollectionBehavior(DisableTestParallelization = true)]

in the AssemblyInfo.cs file. This configuration is also mentioned on XUnit's page (Ref: https://xunit.github.io/docs/running-tests-in-parallel.html - Changing Default Behavior)

Answer 2

Very random code you have shown, and very random details about what is failing. So maybe my suggestions doesn't make sense to your problem.

Instead of calling TestLogTarget directly, then you should setup a logging configuration:

var target = new TestLogTarget() { Name = "Test" };
NLog.Config.SimpleConfigurator(target);
var logger = NLog.LogManager.GetCurrentClassLogger();
logger.Info("Hello World");

Make sure to add a lock around the access to the Messages. Either by making a ToArray() while holding the lock (or calling Contains while holding the lock)

Remember that NLog is a global engine, which require special effort in a unit testing environment where test-classes, test-appdomains are stopped and started frequently, so you need to know your unit-test-system and your nlog-system to make them work together.