5626463547 | San Jose, CA 95126

How to work with console logging in the Mocha Framework

The audience of this post is for software engineers. Software engineers in test will probably get the most out of this, but what I will show you in this post applies even if you are writing only unit tests.

Objective: You want to write some tests in the very popular testing framework, Mocha. Now after every test runs, what you want to do is get information about your test such as the test title, test duration, its state, and what is most pertinent to this post, you want the details that were logged to the console as well as any stack trace in the case of a failure. Let’s call the object that would normally hold all of that information the TestContext. So after your test is completed, you should reference your TestContext and do something with its information. In my case, what I want to do is collect that data and send that to a test management system so that I don’t have to look at test results in multiple places (e.g., where tests and their results are managed, and also on the build agent in Jenkins, TFS, Team City, whatever, or also in a log file on a box somewhere).

Problem: It turns out to be a major pain to get all of that information. Mocha provides the ability to access some of that information after a test is complete. Getting access to the information logged in the console is tricky. I spent hours today looking for a solution online and I found none. After some playing around, I found an implementation that is easy to use and it works.

Overview of this postFirst I am going to setup a very basic NodeJs project and install Mocha (v5.0.0) with the Node Package Manager. For the assertion package, I will use one provided out of the box. Then we’ll see what information we can access. I am not going to worry about transpiling, color coding the output, or anything else. I am going to solve the problem of how to get to the console stdout and stderr, whether a test passes or fails, after a test is completed.

Project: 

This is a screen shot of the project in Webstorm. I have the boilerplate example from the Mocha site with some additional logging to the console. There is a single file test file with one test case. This test passes.

What we want to do now is after the test runs, we want to see what information is available to access about the test. To do that, we will add a hook that Mocha provides called afterEach(). Then what we want to is just log to the console some data about the test. (Obviously, this would need to be replaced with something that can update our testing repository.)

So what you see at the bottom here is that I have logged the state of the current test as well as the duration. Some testing frameworks in other languages also capture everything that is logged to the console during the duration of the test. Can we capture that as well? Well, try as we might, it won’t be there. I will put a breakpoint right after the last console and expose the properties on this.currentTest.

Nothing there about output. You can look under this.currentTest.ctx, or this.currentTest.ctx.test, but you won’t find it. So if you wanted to capture your data that was logged to the console and send it as additional information, you are out of luck. Unless you capture that data some other way and make it available. I’ll show you how.

First, we are going to install a npm package called capture-consoleThen we will wrap the test. So now our test looks like this:

At the top I imported the module. Then inside the Mocha test, I placed the test content into a function that assigns output to a variable called output. The this keyword is in the context of the test. So the theory is that when Mocha passes the test to the afterEach hook, it will include the data assigned to the output. So if I run this test and log the output in the afterEach function, I will see the console log information duplicated.

The output was added to stdout, and stderr is empty since no error was thrown.

But why did I put all of the test in the try-catch block? Watch what happens when I remove the try-catch (and the code in the catch), and then make the test fail by intentionally causing the assertion of fail.

The first line to print the test is starting is run. Then the next line, which contains the assertion, fails. And since the assertion line contains no message, nothing is printed.. But then it skipped to the afterEach, printed that the test failed and it ran for 7ms. But look at output: it is undefined.  Oops.

But when the try-catch is back and the assertion is left to intentionally fail, we get this result:

The try-catch block allows the failed assertion to be caught, handled gracefully, and move into the afterEach. Notice that the afterEach printed the console again. But notice that the test is listed as “passed”. Crap. On the one hand, if we do not wrap with a try-catch,  the failed assertion ends up leaving the output undefined. What good is it if we have tests that might fail but we cannot capture the logging to determine why they fail? On the other hand, if a test fails and the test state is marked as passed, we have failed tests being reported back as passed. Is there a way out of this? Arguably, the first one is worse, because the second one is easily solvable.

To solve this, we just need to add one line within try-catch block.

When an assertion fails or your test failed because of some unforeseen runtime error in your own buggy code, your test will be marked as failed and worthy of your investigation.

And that’s it.

2018-02-18T23:48:03+00:00 February 18th, 2018|0 Comments

Leave A Comment