.NET Core Logging only logs for the first test case

[jcurl]

I'm attaching a very simple example on reproduction testlog.zip

Description

If I run TestCase1 on its own, or TestCase2 on its own, then output from logging is captured and can be analysed. If I run them both, then generally the output of TestCase1 is captured, but not TestCase2, depending on which test case runs first (e.g. TestCase1). If I modify sources so that the ILoggerFactory is instantiated before every test case, then it appears to work as expected, but this makes the assumption that code under test won't do this (and so this is not a suitable workaround).

I used dotPeek as a symbol/source server, so some of the code might differ from what's published as sources. I was able to determine that the problem comes down to how the logs are written into a stringbuilder, but I do not understand enough of the NUnit sources to figure out where the root cause is, only that the underlying code is getting the log messages, but not recording it to the output.

I'd like to know if this is a bug in NUnit, and if not, how it might be possible to workaround.

Version: netcoreapp3.1
Environment: Debugging within VSIDE 2019

  <ItemGroup>
    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="16.10.0" />
    <PackageReference Include="NUnit" Version="3.13.2" />
    <PackageReference Include="NUnit.Analyzers" Version="3.1.0" />
    <PackageReference Include="NUnit.ConsoleRunner" Version="3.12.0" />
    <PackageReference Include="NUnit3TestAdapter" Version="4.0.0" />
    <PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="3.1.0" />
    <PackageReference Include="Microsoft.Extensions.Configuration.Abstractions" Version="3.1.0" />
    <PackageReference Include="Microsoft.Extensions.Configuration.Json" Version="3.1.0" />
    <PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="3.1.0" />
    <PackageReference Include="Microsoft.Extensions.Logging.Configuration" Version="3.1.0" />
    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="3.1.0" />
    <PackageReference Include="System.Threading" Version="4.3.0" />
  </ItemGroup>

Preanalysis

The internal class Microsoft.Extensions.Logging.Logger.Log<TState>(LogLevel, EventId, TState, Exception, Func<TState, Exception, string>) is called.

    public void Log<TState>(
      LogLevel logLevel,
      EventId eventId,
      TState state,
      Exception exception,
      Func<TState, Exception, string> formatter)
    {
      MessageLogger[] messageLoggers = this.MessageLoggers;
      if (messageLoggers == null)
        return;
      List<Exception> exceptions = (List<Exception>) null;
      for (int index = 0; index < messageLoggers.Length; ++index)
      {
        ref MessageLogger local = ref messageLoggers[index];
        if (local.IsEnabled(logLevel))
          LoggerLog(logLevel, eventId, local.Logger, exception, formatter, ref exceptions, in state);
      }
      if (exceptions == null || exceptions.Count <= 0)
        return;
      Logger.ThrowLoggingError(exceptions);

The value local.IsEnabled(Debug) is true, and LoggerLog is called, which just calls:

logger.Log<TState>(logLevel, eventId, state, exception, formatter);

The above goes into ConsoleLogger.Log<TState>(...), it writes successfully the WriteMessage internally, which adds to a queue, and a separate thread is then responsible for writing this to the output. This is done by

this._queueProcessor.EnqueueMessage(message1);

Hence we can tell that the Microsoft Logger did receive the log message.

Then method EnqueueMessage is in the class ConsoleLoggerProcessor, and internally puts the message on a queue.

this._messageQueue.Add(message);
return;

In parallel a thread is reading from the queue and writing to the console calling WriteMessage.

foreach (LogMessageEntry consuming in this._messageQueue.GetConsumingEnumerable())
  this.WriteMessage(consuming);

In the WriteMessage we see:

internal virtual void WriteMessage(LogMessageEntry message) {
  IConsole console = message.LogAsError ? this.ErrorConsole : this.Console;
  if (message.TimeStamp != null)
    console.Write(message.TimeStamp, message.MessageColor, message.MessageColor);
  if (message.LevelString != null)
    console.Write(message.LevelString, message.LevelBackground, message.LevelForeground);
  console.Write(message.Message, message.MessageColor, message.MessageColor);
  console.Flush();
}

and that the console is a Sytem.IO.TextWriter.SyncTextWriter, and it has an internal property _out which is of type NUnit.Framework.Internal.Execution.TextCapture.

It is simply defined in WindowsLogConsole as:

this._textWriter = stdErr ? System.Console.Error : System.Console.Out;

I put a breakpoint in NUnit.Framework.Internal.Execution.TextCapture.Write here:

    public override void Write(string value)
    {
      TestExecutionContext currentContext = TestExecutionContext.CurrentContext;
      if (currentContext != null && currentContext.CurrentResult != null)
        currentContext.CurrentResult.OutWriter.Write(value);
      else
        this._defaultWriter.Write(value);
    }

and I can see that value is the debug message I'm printing. For some reason though, it is not showing up in the output of my test case.

The actual Write method looks like:

    public override void Write(string? value)
    {
      if (!this._isOpen)
        throw new ObjectDisposedException((string) null, SR.ObjectDisposed_WriterClosed);
      if (value == null)
        return;
      this._sb.Append(value);
    }

and the value is being appended to _sb, but appears as though it might be for the previous test case still, even though it isn't printed there.

So NUnit did receive the debug message, but there seems to be some synchronization missing that it doesn't show up in the debug outputs.

[Dreamescaper]

Logging to console is not a reliable way to log something to test results, especially when multiple threads are involved (see here). The recommended way is to use TestContext.WriteLine method.
I don't think there's any existing TestContext logging provider, but you can probably implement your own. I've modified XUnitLoggerProvider, you can try whether it works for you. You can add it via .AddProvider(new NUnitLoggerProvider()).

NUnitLoggerProvider.cs

Concerning behavior, that you've observed. TestExecutionContext.CurrentContext property is similar to ThreadLocal property, i.e. value depends on the executing thread. But with ConsoleLogger writing to console actually happens from single thread - the one processing the queue. I assume that CurrentContext always corresponds to the test which created the logger because of that.

[jcurl]

Thank you for your reply. I appreciate very much you provided a sample ILogger implementation, I look forward to learning more how to do proper logging in .NET Core.

I was wondering though if the root cause of the problem should be understood, as this doesn't appear to be a race condition to the threaded behaviour of the ConsoleLogger (I can accept that perhaps logging is lost or moved to the wrong test case at the end because of the threaded behaviour of the ConsoleLogger), but that it only works for the first test case, unless I completely reinitialize everytime the LoggerFactory?

When I was singlestepping through the code, it appears that the StringBuilder that is being written to contains data from the first test, but because the first test is completed, it's no longer logged and that's why it's being lost. Perhaps there's a condition there that works quite reliably when I use a Console.WriteLine, but not the ConsoleLogger, which at the very end also uses a Console.WriteLine too.

After reading the specification, it does appear though that the authors want to remove this completely (it would be nice to know when, I've got a lot of my code that depends on this)!.

[Dreamescaper]

As I mentioned - problem is that ConsoleLogger uses a separate thread to invoke Console.WriteLine, and this thread is created in the first executed test.

NUnit uses thread info to associate console messages to particular test, and the actual logging thread is always the same - from that first test.

it does appear though that the authors want to remove this completely

You mean NUnit authors? I might be wrong, of course, but I seriously doubt that will ever happen, as that would be hell of a breaking change for a lot of people.
(That spec is quite old)

[jcurl]

Hi @Dreamescaper, now it's clear

NUnit uses thread info to associate console messages to particular test, and the actual logging thread is always the same

And that thread is constant as I saw from MS code, so NUnit can't know. I appreciate your time. I'll close this ticket as resolved and I'll work on my own NUnit ILogger based on your example.

[jcurl]

You mean NUnit authors?

Yeah, the documentation you pointed to has "Trace and Log output will no longer be handled by NUnit at all.".

[mikkelbu]

Note that trace and Log output are not handled specially by NUnit now. The bullet in the specification was written when creating NUnit version 3, as version 2 had special handling of trace and of log4net. This is no longer the case.

From #1139 (comment)

You may be aware that the NUnit 2.x GUI was able to capture console stdout and error, trace output and log4net log output. You could specify as a setting which of those should be captured and displayed in the gui. In the case of trace and log, output continued to be written to it's original destination in addition to appearing in the gui.

With NUnit 3.0, I decided that this needed to be simplified. NUnit was trying to do too many things and they were not all working well together. So, with 3.0, we only capture stdout and stderr and there is no option to prevent this from happening.