NLog custom LayoutRenderer is rendering log events as empty string

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

The problem

From the sample code below which can be run to reproduce the problem, we have 2 custom LayoutRenderer: RendererOne and RendererTwo. Those 2 are then used in tests TestA and TestB respectively. When i run the test one at a time, I do not get any problem. However, if were to run them in one go example via XUnit's "Run All" button, I get failed assertions as illustrated in the attached image below:

It would appear that the Renderer attached to the target is producing empty strings ("" in the output) when it encounters a LogEventInfo object in the Append method of the LayoutRenderer. As it can be seen in the sample code, I have enabled the InternalLogger but, it is not showing me what could be going wrong. I think that I have done everything correctly in terms of how to use a custom renderer:

• Register the Renderers (Ref: constructors of TestA and TestB)
• Assign them to the relevant TestTarget (Ref: constructor of Log)

I do not know why the Layout which is not processing the log events correctly is not being registered. Here is another screenshot which illustrates this situation:

Note the above screenshots are not related but serves to illustrate the situation. Any kind of explanation/fix/how-to-troubleshoot the problem would be most welcome.

"Ready" to run code

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

namespace LoggingTests
{
    [Target("test-target")]
    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 Log
    {
        private string _target_name;

        public Log(Layout layout,
                   string target_name)
        {
            if (LogManager.Configuration == null)
            {
                LogManager.Configuration = new LoggingConfiguration();
                InternalLogger.LogFile = Path.Combine(Environment.CurrentDirectory,
                                                      "nlog.debug.txt");
                InternalLogger.LogLevel = LogLevel.Trace;
            }

            _target_name = target_name;
            if (LogManager.Configuration.FindTargetByName<TestTarget>(_target_name) == null)
            {
                // Create the target:
                TestTarget target = new TestTarget(_target_name);

                // Register the target:
                Target.Register<TestTarget>(_target_name);

                // Assign layout to target:
                target.Layout = layout;

                // Add the target to the configuration:
                LogManager.Configuration.AddTarget(_target_name,
                                                   target);

                // Add a logging rule pertaining to the above target:
                LogManager.Configuration.AddRule(LogLevel.Trace,
                                                 LogLevel.Fatal,
                                                 target);

                // Because configuration has been modified programatically, we have to reconfigure all loggers:
                LogManager.ReconfigExistingLoggers();
            }
        }

        public void AssertLogContains(string message)
        {
            TestTarget target = LogManager.Configuration
                                          .FindTargetByName<TestTarget>(_target_name);
            target.Messages.Should().Contain(message);
        }
    }

    class Loggable
    {
        private Logger _logger;

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

        public void Error(string message)
        {
            _logger.Error(message);
        }

        public void Info(string message)
        {
            _logger.Info(message);
        }
    }

    [LayoutRenderer("renderer-one")]
    class RendererOne : LayoutRenderer
    {
        protected override void Append(StringBuilder builder,
                                       LogEventInfo logEvent)
        {
            builder.AppendFormat($"{GetType().Name} - {logEvent.Level.Name}: {logEvent.Message}");
        }
    }

    [LayoutRenderer("renderer-two")]
    class RendererTwo : LayoutRenderer
    {
        protected override void Append(StringBuilder builder,
                                       LogEventInfo logEvent)
        {
            builder.AppendFormat($"{GetType().Name} - {logEvent.Level.Name} -> {logEvent.Message}");
        }
    }

    public class TestA
    {
        private Log _log;

        public TestA()
        {
            LayoutRenderer.Register<RendererOne>("renderer-one");
            _log = new Log("${renderer-one}", GetType().Name);
        }

        [Fact]
        public void SomeTest()
        {
            Loggable l = new Loggable();
            l.Info("Test A - SomeTest");
            l.Error("Test A - SomeTest");
            _log.AssertLogContains("RendererOne - Info: Test A - SomeTest");
            _log.AssertLogContains("RendererOne - Error: Test A - SomeTest");
        }

        [Fact]
        public void AnotherTest()
        {
            Loggable l = new Loggable();
            l.Info("Test A - AnotherTest");
            l.Error("Test A - AnotherTest");
            _log.AssertLogContains("RendererOne - Info: Test A - AnotherTest");
            _log.AssertLogContains("RendererOne - Error: Test A - AnotherTest");
        }
    }
    public class TestB
    {
        private Log _log;

        public TestB()
        {
            LayoutRenderer.Register<RendererTwo>("renderer-two");
            _log = new Log("${renderer-two}", GetType().Name);
        }

        [Fact]
        public void SomeTest()
        {
            Loggable l = new Loggable();
            l.Info("Test B - SomeTest");
            l.Error("Test B - SomeTest");
            _log.AssertLogContains("RendererTwo - Info -> Test B - SomeTest");
            _log.AssertLogContains("RendererTwo - Error -> Test B - SomeTest");
        }
    }
}

Note you will have to install the dependency libraries mentioned in the "Environment" section of this question in order to run it. Also, it might be that you have to run the code couple of times in order for it to fail as shown above. Thanks in advance.

Answer 1

I posted the question on the Issue page of NLog on GitHub (Ref: https://github.com/NLog/NLog/issues/2525). The suggestion by Rolf to explicitly disable parallel execution of Xunit via this line:

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

in the AssemblyInfo.cs made the problem go away. Note, this is needed in the above environment even if i explicitly indicated in the Visual Studio Runner of XUnit not to do parallel runs.