NUnit Console Runner and NLog extension logging for your tests

Have you experienced the frustration of tests running perfectly well on your local machine and then failing in CI? This all too familiar "It worked on my machine" comes to mind. You set off to investigate and after a while you realize you are too far into the rabbit hole between code and logs in Kibana and this investigation is getting you nowhere. Wouldn't it be nice if you could hijack the logger and print the logs in the test runner's console? TL;DR NLog can be extended easily and NUnit Console Runner does not play well with simple console logs. 

Photo by Kaboompics .com from Pexels

Enter Console logging

In .Net in general it is not advisable to log to console in a multi-threaded environment, because the console is not thread safe. While logging simple strings may not cause any problems logging strings with interpolated variables may very well be sub optimal to say the least. Should you use any such debugging technique you are better off with a thread safe file logging framework. 

NUnit console runner in that respect is no different. It executes tests in batch and produces results in its own colorful console. In fact, there is also a big chance you will see any regular Console.WriteLine messages when you run it on your local machine. 

Things however get weird when you are trying to see these logs in your CI. We are using Teamcity at work and the logs are scarce. Everything not assertion or exception related is just filtered out. This coincides with my experience when debugging thread heavy applications. Logs would not appear in the console and the only way to debug those apps was via a thread safe logger.  

Extending your logging framework (in this case NLog)

There are a few ways to extend a logger. Depending on the architecture of your code you may be able to implement an interface and inject that to you tests or inherit a wrapper around your logger and override its methods. In the case of NLog however all one has to do is create an NLog extension and tweak the nlog.config file. The article may be from 2015 but the information is extremely accurate.

The extending part is easy. Now to tackle the logging part. Where do we want to print the logs? If we wanted to use files we needn't extend anything. What we do want is see our system's logs in our CI's logs. If we do want to do that we want to make sure that our logger is not under an AsyncWrapper in our nlog.config. That may work if your system is simple and doesn't have threads involved, chances are however it is not and it has threads and I/O connections of all sorts and colors (on integration or E2E tests for example), not to mention async/await calls. So regular console logging will not work here. It can help us for an initial test to check the extension is registered and working properly.

Printing the logs

Since we are trying to print logs via flows in our system produced by our tests and test runners run tests in batches (which would also mean threads) and we are testing pars of a complex system and we want to make sure the logs appear as part of the test result.

In the case of NUnit the most usual runner plugin in a CI like Teamcity is the NUnit Console Runner. While it encompasses the NUnit engine it also has its own colorful console.

Since the runner in Teamcity is the console runner what one can do is download and install the runner and see the logs for oneself. This is all fine but how do we write those logs? Well NUInit gives us a few options:

• Regular logging:

  TestContext.WriteLine("This is my log line")

  Will not work acts like a regular console
• Current test's context:

  TestContext.CurrentContext.WriteLine("This is my log line") 

  Will not work acts like a regular console
• Using the console runner's different out streams as quoted in the NUnit documentation:

Out

Gets a TextWriter used for sending output to the current test result.

Error

Gets a TextWriter used for sending error output intended for immediate display.

Progress

Gets a TextWriter used for sending normal (non-error) output intended for immediate display.

Out of the three last options the only one who worked properly in the NUnit-NLog-Teamcity setup was TestContext.Progress.WriteLine("My message"). And when I say properly I mean that the relevant logs showed up in the Teamcity build log before and after a failing or succeeding test but the ones set to output on the test result where nowhere to be found. I would guess that this is the cause of threads over the system, NLog and NUnit Console Runner altogether. That does not mean however that you should not try them all and see what fits best to your setup.

Tests reporting tools and logging 

Among other things in our pipelines we are also using the Allure Framework of  Allure Reports to visualize our test results and look up on trends and groups of errors. The above logging methodology does not provide any logs in test outputs because we are using the Progress TextWriter. However, if we want to have some particular logging on a test on an overnight report we make sure to add calls to the Out or Error TextWriters on that test's code.

Final words

I hope this post will save you, oh lucky reader, from the arduous task of having to figure out all these permutations on your own. I sure had an interesting couple of days arguing with myself over the code and the CI, and so I thought I would spare you the long hours of search and frustration with this post