When logging with NLog, why does output from a library DLL come out in a different format?

Question

I have some code that uses NLog and I like to capture this output in my unit tests so I can see what's going on. I use MSpec as my test framework and NCrunch as the test runner. I configre logging once per test assembly, like this:

    public class LogSetup : IAssemblyContext
    {
    static Logger log;

    public void OnAssemblyStart()
        {
        var configuration = new LoggingConfiguration();
        var unitTestRunnerTarget = new TraceTarget();
        configuration.AddTarget("Unit test runner", unitTestRunnerTarget);
        unitTestRunnerTarget.Layout =
            "${time}|${pad:padding=-5:inner=${uppercase:${level}}}|${pad:padding=-16:inner=${callsite:className=true:fileName=false:includeSourcePath=false:methodName=false:includeNamespace=false}}|${message}";
        var logEverything = new LoggingRule("*", LogLevel.Trace, unitTestRunnerTarget);
        configuration.LoggingRules.Add(logEverything);
        LogManager.Configuration = configuration;
        log = LogManager.GetCurrentClassLogger();
        log.Info("Logging initialized");
        }

    public void OnAssemblyComplete() { }
    }

There are no XML configuration files anywhere and this is the only place the logging configuration is set.

When I run the unit tests, I get output like this example:

22:37:51.0253|DEBUG|SimulatorState  |Transitioning from  => TA.DigitalDomeworks.HardwareSimulator.StateStartup
22:37:51.1263|DEBUG|SimulatorState  |Transitioning from TA.DigitalDomeworks.HardwareSimulator.StateStartup => TA.DigitalDomeworks.HardwareSimulator.StateReceivingCommand
nCrunch.TestHost462.x86.exe Information: 0 : 22:37:51.5923|INFO |TransactionObserver|Transaction pipeline connected to channel with endpoint Simulator:Fast
nCrunch.TestHost462.x86.exe Information: 0 : 22:37:51.7393|INFO |TransactionObserver|Committing transaction TID=1 [GINF] [{no value}] 00:00:10 Created
22:37:51.7623|DEBUG|c__DisplayClass0_1`1|StatusTransaction[1]: Subscribe()
nCrunch.TestHost462.x86.exe Information: 0 : 22:37:51.7932|INFO |SimulatorState  |State [ReceiveCommand] received stimulus 'G'
nCrunch.TestHost462.x86.exe Information: 0 : 22:37:51.7932|INFO |SimulatorState  |State [ReceiveCommand] received stimulus 'I'
nCrunch.TestHost462.x86.exe Information: 0 : 22:37:51.7943|INFO |SimulatorState  |State [ReceiveCommand] received stimulus 'N'
nCrunch.TestHost462.x86.exe Information: 0 : 22:37:51.7943|INFO |SimulatorState  |State [ReceiveCommand] received stimulus 'F'
22:37:51.7943|DEBUG|SimulatorState  |Transitioning from TA.DigitalDomeworks.HardwareSimulator.StateReceivingCommand => TA.DigitalDomeworks.HardwareSimulator.StateExecutingCommand
22:37:51.7943|DEBUG|StateExecutingCommand|Processing command [GINF]
22:37:51.7943|DEBUG|SimulatorState  |Transitioning from TA.DigitalDomeworks.HardwareSimulator.StateExecutingCommand => TA.DigitalDomeworks.HardwareSimulator.StateSendStatus

As you can see, the log output gets written using two different layouts. The first couple of lines are as expected, then there's this monstrosity:

nCrunch.TestHost462.x86.exe Information: 0 : 22:37:51.5923|INFO |TransactionObserver|Transaction pipeline connected to channel with endpoint Simulator:Fast

It's almost like the output got formatted twice, once using a default format and then again using the format I want. There doesn't seem to be a pattern as to when the "odd" output happens. In line 1, the ouput came from class SimulatorState, then in line 6 there is more output from SimulatorState but this time it is in the mutant format.

How can this be?