Taking the noise out of logs to quickly find build issues

This blog post will focus on one of the JavaScript unit test runners, Karma, but you should be able to take these principles and apply them to whatever unit test runner you are using in your tech stack.

The problem

We had a nice problem - we were getting into the lofty heights of 75% percent coverage with over 6,500 unit tests over a decent sized front-end codebase. It's worth noting that we're not hugely focussed on percent coverage as a metric (instead we like to make sure business logic is well covered), however it's an easily digestible metric that people understand.

The problem we were having was that the console output for each unit test run was becoming unmanageable. Each test run was generating around 1.4 megabytes of text. This may not sound like a lot going by the filesize, but it's certainly a lot of text for a human to scroll through.

A good example of this level of output being a hindrance, is getting a test failure early in the test run. At the end of the run, you'll get a message telling you that a test failed, somewhere:

Chrome Headless 122.0.6261.94: Executed 6609 of 6752 (skipped 142) 1 FAILED (38.304 secs / 34.228 secs)
TOTAL: 6609 SUCCESS 1 FAILED

Now in order to find that failed test, we'll need to do a lot of scrolling, or re-run the tests and this time pipe the output to a text file, so that we can easily search through the output for the failure. Aside from losing all of our helpful text colouring in the console, having to open the text file and search is friction we could do without.

What exactly is causing the noise

All we really need to see in the test run output is what failed and perhaps a count of how many passed.

However, there were a few reasons the test run output was so big:

1. Non fatal warnings being logged out to the console

Each time there was a call to our mocked backend an endpoint that wasn't mocked fully, we'd get a warning. This would happen even if there was no failure.

2. All levels of console messages being logged

This includes information and warning messages. Again, neither are an indicator of anything fatal.

3. Too much information in the progress output

Chrome Headless 122.0.6261.94: Executed 0 of 6752 SUCCESS (0 secs / 0 secs)
Chrome Headless 122.0.6261.94: Executed 1 of 6752 SUCCESS (0 secs / 0.015 secs)
Chrome Headless 122.0.6261.94: Executed 2 of 6752 SUCCESS (0 secs / 0.02 secs)
Chrome Headless 122.0.6261.94: Executed 3 of 6752 SUCCESS (0 secs / 0.025 secs)
Chrome Headless 122.0.6261.94: Executed 4 of 6752 SUCCESS (0 secs / 0.029 secs)

The above was being logged for each an every test - again, information that is of little value to anyone that wants to know if the entire test suite passed or not.

Aside from inconveniencing developers, it was also creating a lot of work for our build server's logs. We run this test suite for every branch, every time there is a push. That's a lot of unnecessary output to wade through when you need to.

The solution

The goals:

• Only see valuable information in the test run output on the dev machines
• Not to pollute the build server logs with too much unnecessary information

We tackled this by taking two different approaches.

1. Hide all non fatal warnings

Most unit test runners will allow you to configure this centrally. In the case of Karma, this is easily done by specifying the level of logs to actually print.

2. Running a much "quieter" Karma reporter on the build server

Instead of outputting the progress report in a verbose manner on the build server, we instead opted to run the "failed" reporter on the build server. This instead only prints a "." for each passing test, whilst still printing the full stack trace when there is a test failure.

This drastically reducing the build log output and made it much easier to find the valuable information in the build log.