Mark Oliver's World

Posted: 16/12/2023

Querying Console Output In Your Tests

Hello, and welcome to my blog post for December 16th of the C# Advent Calendar 2023.

Organised by Matthew Groves.

I wont tell you about me, but if you are interested, check out my About me page.

Last year in one of the C# advent calendars, I wrote about Testing in Dotnet.

I find that Unit Testing is a topic that is not discussed as often as needed, and considering that article has had over 2.1k views, I decided that it made sense to write about testing once again.

This time I am going to talk about how I tested a black box system that despite having the code available, could not be refactored to be easier to test with unit tests.

The system in question was a telecomms messaging parser, and was a large and complicated beast. It had no documentation, and none of the implementing software engineers were still with the business.

So inevitably, it had no unit tests either 😱 ! However, it was not completely bereft of tests, it did have some higher level integration style tests.

These tests took a network capture (See Wireshark ), and ran it through the parser, and confirmed that the emissions of the parser were what was expected (Think of it like snapshot testing)

This in theory is a very sound testing strategy for this kind of setup, however the emissions of the parser were very generic, and did not indicate if certain conditions had been met. 😢

What this meant is that over time, the system changed internally and certain code paths were not being executed any more, but due to the state of the final emission it was assumed everything was correct.

Due to the nature of the input, and the system, the existence of the final emission was not enough to prove that the system functioned correctly, and many edge cases were not working.

Therefore, without a major rewrite, how do we confirm that the system is following the correct path?

Well one thing it did well was it logged its internals constantly, which made the job of analysing the issues much easier for the service desk team to help the customers.

But as a software engineer I thought, "Can we use those logs as part of the validation of the system in the automated tests?"

Turns out the answer is Yes!. Dotnet is a very flexible framework, and you can pretty much override anything if you know the right magical incantation.

The first thing was to determine how the system is doing its extensive logging.

This turned out to be the log4net logging platform with a bespoke format, and some bespoke handlers added.

Now we know that, we "could" have our tests read the log files directly and parse them for the required items!

This was a great idea, but did not give the feedback we wanted in the unit tests. We would get a test failure, and then have to find the logs and determine why.

So instead, can we redirect those logs to the MSTest Console Output?

That way when we get a failure, we have all the information we need to diagnose the problem further (vital when running external devops agents!)

Turns out this is easy to do with log4net, we can use a ConsoleAppender.

So adding this to our `log4net`` config specifically in the unit tests, gives us the internals of the system redirected to the Console:

            <appender name="Console" type="log4net.Appender.ConsoleAppender">     <layout type="log4net.Layout.PatternLayout">         <conversionPattern value="%date %-5level: %message%newline" />     </layout> </appender>

That is useful for sure, we now have all the info in the same place in a failure of the test.

However can we make the tests more useful?

Can they analyse the output in the Console and identify the problems themselves?

Again, yes! Dotnet to the rescue!

We can override the Console output destination to something of our choosing. For us that was a StringBuilder:

            public static (TextWriter originalConsoleOut, StringBuilder consoleOutput) CaptureConsoleOut() {     //Capture all the Console.Write output to a StringBuilder     StringBuilder consoleOutput = new StringBuilder();     TextWriter originalConsoleOut = Console.Out;     Console.SetOut(new StringWriter(consoleOutput));     consoleOutput.Clear();     return (originalConsoleOut, consoleOutput); }

If we add this code, to our TestInitialize method, then all tests can now get access to the console output.
We can do that by defining the TestContext property, that MSTest will then automatically handle and populate.
This is then available in all parts of the test lifecycle. So in the initialise, we are storing the StringBuilder that will contain the Console output and the original TextWriter used as the Console Output (so we can reinstate it later) as a Tuple within the TestContext Properties Dictionary.

            public TestContext TestContext{ get; set; }  [TestInitialize] public void TestInitialize() {     TestContext.Properties["consoleOutInfo"] = CaptureConsoleOut(); }

We are nearly there now. But we have captured all the Console output, so it is no longer displayed in the TestRunner, therefore at the end of the test, we need to force the text intercepted back to the real console, which we will do in the TestCleanup method:

            
              [TestCleanup]  public void TestCleanup()  {     var consoleOutInfo = ((System.IO.TextWriter originalConsoleOut, System.Text.StringBuilder consoleOutput))TestContext.Properties["consoleOutInfo"];      //Reset the Console output back to the original output stream     Console.SetOut(consoleOutInfo.originalConsoleOut);          //Push the captured data to the original outputstream     Console.WriteLine(consoleOutput.ToString());  }

So now in our tests, we can query the consoleOutput StringBuilder's contents at any time in the test, and Assert what the black box system is doing e.g.

            var consoleOutInfo = ((System.IO.TextWriter _, System.Text.StringBuilder consoleOutput))TestContext.Properties["consoleOutInfo"];  Assert.IsTrue(consoleOutInfo.consoleOutput.ToString().Contains("COMPRESSING MESSAGE"), "Did not compress the message");

This was a game changer for this type of system, as the end emission being as the stored snapshot was hiding that other parts of the system were not being activated due to missing internal emissions that could not be captured from the Black box.

We can now add additional tests that confirm the path through the code was as expected for each scenario by adding a few simple Asserts based on the logging.

An Afterthought

Some of you may be thinking that this is a very crude approach, and our own implemented TextWriter would be a better choice, and you may be correct, but this was very quick to put in place, so KISS & YAGNI kicked in.

As often in software, "simple is best", and for the effort required to implement this, its benefit was massive.

In an ideal world, we would have a more observable system, but sometimes you just have to work with what you have.

If you got this far through my C# Advent Calendar 2023 article, then thanks a lot, I appreciate your time.

Come say Hi on Twitter

Happy holidays everyone

"A Cat in tinsel saying Happy holidays, dotnet family"

Thanks for reading this post.

If you want to reach out, catch me on Twitter!

I am always open to mentoring people, so get in touch.