Automated software testing part 3: writing tests, and refactoring

Previous: part 2 – Next: part 4

In this post, we will look at the process of writing unit tests for existing code. In the process, we will be refactoring the code to make the tests easier and clearer – and to improve the code.

The code is in node.js with the express framework. However, the approach we will take is not language specific. Reading this post can help you even if you have never written any node.js code.

This is a long post and would have been better as a screencast. When I have created that screencast, I’ll add a link to it in this post.

You can also find the code below in the src/unit-test-1 dir of my blog code repository.

Note: The code snippets contain a few things that should be done differently in production code. For example, using asynchronous fs calls (e.g. fs.readFile instead of fs.readFileSync ); using "use strict;" ; and using modules like log4js and sinon.

Step 1

This is the code we shall write tests for:

// server.js

// Express is a web framework for node.js.
var express = require('express');

// Moment is a date manipulation library.
var moment = require('moment');

// Fs is a core module of node.js to manipulate the file system.
var fs = require('fs');

var app = express();

// When a http request is done on /count/start, execute this code.
// req contains request information, which we are not using.
// res is the response object.
app.get('/count/start', function (req, res) {
  // Read the server log file
  var data = fs.readFileSync(__dirname + '/server.log').toString();

  // and count how many lines contain the words 'server started'.
  var numStartLines = data
    .split(/\r\n|\r|\n/)
    .filter(function(line) { return /server started/.test(line); })
    .length;

  // Send a JSON answer that shows how many times the server has been started.
  res.send({ numStart: numStartLines });
});

var server = app.listen(64001, function () {
  // When the server starts, log that it started.
  var msg = moment().format('YYYY-MM-DD HH:mm:ss') + ' - server started\n';
  fs.appendFileSync(__dirname + '/server.log', msg);
  
  var host = server.address().address
  var port = server.address().port

  console.log("Unit test 1 app v1 listening at http://%s:%s", host, port)
});

// server.js

// Express is a web framework for node.js.

var express = require('express');

// Moment is a date manipulation library.

var moment = require('moment');

// Fs is a core module of node.js to manipulate the file system.

var fs = require('fs');

var app = express();

// When a http request is done on /count/start, execute this code.

// req contains request information, which we are not using.

// res is the response object.

app.get('/count/start', function (req, res) {

// Read the server log file

var data = fs.readFileSync(__dirname + '/server.log').toString();

// and count how many lines contain the words 'server started'.

var numStartLines = data

.split(/\r\n|\r|\n/)

.filter(function(line) { return /server started/.test(line); })

.length;

// Send a JSON answer that shows how many times the server has been started.

res.send({ numStart: numStartLines });

});

var server = app.listen(64001, function () {

// When the server starts, log that it started.

var msg = moment().format('YYYY-MM-DD HH:mm:ss') + ' - server started\n';

fs.appendFileSync(__dirname + '/server.log', msg);

var host = server.address().address

var port = server.address().port

console.log("Unit test 1 app v1 listening at http://%s:%s", host, port)

});

This code starts an HTTP server that listens on localhost:64001 . It writes to a log file whenever it is started. On an HTTP request to http://localhost:64001/count/start , it returns a JSON structure that shows how many times the server has started. Like this:

czapka:~$ curl localhost:64001/count/start
{"numStart":5}

1 2	czapka:~$ curl localhost:64001/count/start {"numStart":5}

We want to test if the correct count is returned by our URL – so the code that is the second argument of app.get('/count/start', function) . How can we do that?

If we load server.js in our test file, the server is actually started and the real log file is being used. This is not an option. Besides, running the server and testing the HTTP call is a high level test – let’s test it on a lower level. To do this, we need to separate the count start function from the server itself.

Step 2

We’ll create a count.js file to put the count start functionality in. It looks like this:

// count.js

var fs = require('fs');

function countStart(req, res) {
  var data = fs.readFileSync(__dirname + '/server.log').toString();
  var numStartLines = data
    .split(/\r\n|\r|\n/)
    .filter(function(line) { return /server started/.test(line); })
    .length;
  res.send({ numStart: numStartLines });
}

module.exports = {
  countStart: countStart
};

// count.js

var fs = require('fs');

function countStart(req, res) {

var data = fs.readFileSync(__dirname + '/server.log').toString();

var numStartLines = data

.split(/\r\n|\r|\n/)

.filter(function(line) { return /server started/.test(line); })

.length;

res.send({ numStart: numStartLines });

}

module.exports = {

countStart: countStart

};

The app.get() line in server.js needs to be changed as well:

// Modifications to server.js

var count = require('./count');
app.get('/count/start', count.countStart);

// Modifications to server.js

var count = require('./count');

app.get('/count/start', count.countStart);

Excellent. Now we can create count.spec.js to test the new countStart function. Let’s give it a shot. We’ll use the mocha framework for testing and should to check actual results against expected results.

// count.spec.js

require('should');

var count = require('./count');

describe('countStart', function() {
  it('should count the number of times the server was started', function() {
    var req = ..?
    var res = ..?
    count.countStart(req, res);
    something.should.equal(somethingElse);
  });
});

// count.spec.js

require('should');

var count = require('./count');

describe('countStart', function() {

it('should count the number of times the server was started', function() {

var req = ..?

var res = ..?

count.countStart(req, res);

something.should.equal(somethingElse);

});

There are a few problems here.

This test will read the real server.log file. Therefore, the number of “server start” lines can be different each time you run this test. Additionally, the file may not exist at all.
The countStart function does not return a useful value; instead it call res.send with the value to be tested. That makes it more difficult to test.

Let’s get it to work anyway, by creating a fake res object with a send method.

// count.spec.js

describe('countStart', function() {
  it('should count the number of times the server was started', function() {
    var dataSent;
    
    var fakeResObject = {
      send: function(data) {
        dataSent = data;
      }
    };

    count.countStart({}, fakeResObject);

    // We know that dataSent should be an object with the key
    // "numStart". However, we don't know the value.
    dataSent.should.have.keys(['numStart']);
    dataSent.numStart.should.be.a.number;
  });
});

// count.spec.js

describe('countStart', function() {

it('should count the number of times the server was started', function() {

var dataSent;

var fakeResObject = {

send: function(data) {

dataSent = data;

}

};

count.countStart({}, fakeResObject);

// We know that dataSent should be an object with the key

// "numStart". However, we don't know the value.

dataSent.should.have.keys(['numStart']);

dataSent.numStart.should.be.a.number;

});

Now we have something that works, most of the time. In my opinion, this is not acceptable test code yet. So let’s fix the first problem, that the test code uses the same server.log file as the server itself.

Step 3

The problem with the current approach, is that the countStart function determines the log file by itself. It would be better if the log file was determined elsewhere, and then given to (or asked by) the countStart function. Ever since I saw Miško Hevery’s talk on Dependency Injection, I’ve been a fan of DI; and even if this is not be exactly DI, it’s certainly very similar.

We’ll move the log file related code to a separate file, log.js and we’ll make it possible to set and get the filename of the log file.

// log.js

var fs = require('fs');
var moment = require('moment');

var logFileName;

function getFile() {
  return logFileName;
}

function setFile(filename) {
  logFileName = filename;
}

function logMessage(message) {
  fs.appendFileSync(getFile(), moment().format('YYYY-MM-DD HH:mm:ss') + ' - ' + message + '\n');
}

module.exports = {
  getFile   : getFile,
  setFile   : setFile,
  logMessage: logMessage,
};

// log.js

var fs = require('fs');

var moment = require('moment');

var logFileName;

function getFile() {

return logFileName;

}

function setFile(filename) {

logFileName = filename;

}

function logMessage(message) {

fs.appendFileSync(getFile(), moment().format('YYYY-MM-DD HH:mm:ss') + ' - ' + message + '\n');

}

module.exports = {

getFile : getFile,

setFile : setFile,

logMessage: logMessage,

};

Additionally, we’ll need a few changes to server.js and count.js.

// server.js changes

var log     = require('./log');
log.setFile(__dirname + '/server.log');

var server = app.listen(64001, function () {
  log.logMessage('server started');
  
  // The old code here
});

// server.js changes

var log = require('./log');

log.setFile(__dirname + '/server.log');

var server = app.listen(64001, function () {

log.logMessage('server started');

// The old code here

});

// count.js

var log = require('./log');

function countStart(req, res) {
  var filename = log.getFile();
  var data = fs.readFileSync(filename).toString();
  // Rest is unchanged.
}

// count.js

var log = require('./log');

function countStart(req, res) {

var filename = log.getFile();

var data = fs.readFileSync(filename).toString();

// Rest is unchanged.

}

We’re getting somewhere.

In our test file, we can now use a different log file. We’ll have to create this file as part of the setup of our test, and remove it at the end. Here’s our modified count.spec.js :

// count.spec.js

require('should');

var fs    = require('fs');
var count = require('./count');
var log   = require('./log');

describe('countStart', function() {
  var logFileName = __dirname + '/unit-test-file.log';

  function cleanupTestFile() {
    if (fs.existsSync(logFileName)) {
      fs.unlinkSync(logFileName);
    }
  }
  // This code is run before each test.
  beforeEach(cleanupTestFile);
  // And this code after each test.
  afterEach(cleanupTestFile);

  it('should count the number of times the server was started', function() {
    var dataSent;
    
    var fakeResObject = {
      send: function(data) {
        dataSent = data;
      }
    };

    fs.appendFileSync(logFileName, '2016-02-20 14:53:09 - server started\n');
    fs.appendFileSync(logFileName, '2016-02-20 14:55:50 - server started\n');

    log.setFile(logFileName);

    count.countStart({}, fakeResObject);
    dataSent.should.eql({ numStart: 2 });
  });
});

// count.spec.js

require('should');

var fs = require('fs');

var count = require('./count');

var log = require('./log');

describe('countStart', function() {

var logFileName = __dirname + '/unit-test-file.log';

function cleanupTestFile() {

if (fs.existsSync(logFileName)) {

fs.unlinkSync(logFileName);

}

// This code is run before each test.

beforeEach(cleanupTestFile);

// And this code after each test.

afterEach(cleanupTestFile);

it('should count the number of times the server was started', function() {

var dataSent;

var fakeResObject = {

send: function(data) {

dataSent = data;

}

};

fs.appendFileSync(logFileName, '2016-02-20 14:53:09 - server started\n');

fs.appendFileSync(logFileName, '2016-02-20 14:55:50 - server started\n');

log.setFile(logFileName);

count.countStart({}, fakeResObject);

dataSent.should.eql({ numStart: 2 });

});

Note that we can now actually test whether the number of lines is 2, because we control the log file in the test. In step 2, we could not predict how many lines there would be. That means that this test tests our function better. In step 2, the countStart function could just as easily always have returned 42, and our test would not have noticed that.

Regarding our DI approach: we’re not injecting the log file name into the countStart function yet, because this function is being called by the express framework. Let’s work on that now. This should also fix the second problem mentioned at the end of step 2.

Step 4

If we look at the countStart function, we see that it is currently doing 2 things: it is handling the HTTP request and sending a response, and it’s counting the “server started” lines in the log file. In general, when a function does 2 things that are easily separated, it’s good to separate the two. This makes the code cleaner, easier to reuse, and easier to test.

Here’s the new count.js:

// count.js

var fs  = require('fs');
var log = require('./log');

function countStart(req, res) {
  var numStartLines = _countStart(log.getFile());
  res.send({ numStart: numStartLines });
}

function _countStart(filename) {
  var data = fs.readFileSync(filename).toString();
  var numStartLines = data
    .split(/\r\n|\r|\n/)
    .filter(function(line) { return /server started/.test(line); })
    .length;
  return numStartLines;
}

module.exports = {
  countStart: countStart
};

// count.js

var fs = require('fs');

var log = require('./log');

function countStart(req, res) {

var numStartLines = _countStart(log.getFile());

res.send({ numStart: numStartLines });

}

function _countStart(filename) {

var data = fs.readFileSync(filename).toString();

var numStartLines = data

.split(/\r\n|\r|\n/)

.filter(function(line) { return /server started/.test(line); })

.length;

return numStartLines;

}

module.exports = {

countStart: countStart

};

The function countStart now only gets the number of “server start” lines from elsewhere, and returns a data structure. The _countStart function (ok, the name could have been better) no longer has any knowledge about HTTP requests or responses, and just counts lines in a file.

This also means that we should test both functions. Both tests will be easier than the single test of step 3.

First, we’ll test _countStart . Currently, this function is not listed in the exports of count.js , because it’s a private function (maybe it should be, especially if we want to use this functionality in other parts of the cade). There is a trick to get access to this function in our test suite, and that trick is the rewire module.

This is how we test _countStart .

// count.spec.js first part

  describe('_countStart', function() {
    var logFileName = __dirname + '/unit-test-file.log';
    function cleanupTestFile() {
      if (fs.existsSync(logFileName)) {
        fs.unlinkSync(logFileName);
      }
    }
    beforeEach(cleanupTestFile);
    afterEach(cleanupTestFile);

    it('should count the number of times the server was started', function() {
      var dataSent;
      
      fs.appendFileSync(logFileName, '2016-02-20 14:53:09 - server started\n');
      fs.appendFileSync(logFileName, '2016-02-20 14:55:50 - server started\n');

      // Get the private _countStart function. We use rewire, because the
      // function is not in module.exports so we can't access it directly.
      var _countStart = count.__get__('_countStart');

      var numStart = _countStart(logFileName);
      numStart.should.equal(2);
    });
  });

// count.spec.js first part

describe('_countStart', function() {

var logFileName = __dirname + '/unit-test-file.log';

function cleanupTestFile() {

if (fs.existsSync(logFileName)) {

fs.unlinkSync(logFileName);

}

beforeEach(cleanupTestFile);

afterEach(cleanupTestFile);

it('should count the number of times the server was started', function() {

var dataSent;

fs.appendFileSync(logFileName, '2016-02-20 14:53:09 - server started\n');

fs.appendFileSync(logFileName, '2016-02-20 14:55:50 - server started\n');

// Get the private _countStart function. We use rewire, because the

// function is not in module.exports so we can't access it directly.

var _countStart = count.__get__('_countStart');

var numStart = _countStart(logFileName);

numStart.should.equal(2);

});

This looks very similar to the test in step 3. The difference is, that we don’t fiddle around with a fake response object anymore: _countStart simply returns the count.

The other test is of countStart. In this test, we use a very important principle: we don’t need to test what has already been tested elsewhere. Therefore, we are going to replace the _countStart function be a function of our own. This is called monkey patching.

// count.spec.js second part

  describe('countStart', function() {
    it('should respond with the number of times the server was started', function() {
      var dataSent;
      var fakeResObject = {
        send: function(data) {
          dataSent = data;
        }
      };

      var logFileName = 'testfile.log';
      log.setFile(logFileName);

      var logFileArgument;

      // We overwrite the private _countStart function so it returns what we
      // want. After all, we are testing the countStart function here; the
      // _countStart function has already been tested above.
      // Also, we want to verify that countStart calls _countStart with the correct
      // filename argument. 
      // The __set__() call returns a function that, when called, resets the
      // overwritten function back to its original.
      var reset = count.__set__('_countStart', function(filename) {
        logFileArgument = filename;
        return 2;
      });

      count.countStart({}, fakeResObject);

      dataSent.should.eql({ numStart: 2 });
      logFileArgument.should.equal(logFileName);

      reset();
    });
  });

// count.spec.js second part

describe('countStart', function() {

it('should respond with the number of times the server was started', function() {

var dataSent;

var fakeResObject = {

send: function(data) {

dataSent = data;

}

};

var logFileName = 'testfile.log';

log.setFile(logFileName);

var logFileArgument;

// We overwrite the private _countStart function so it returns what we

// want. After all, we are testing the countStart function here; the

// _countStart function has already been tested above.

// Also, we want to verify that countStart calls _countStart with the correct

// filename argument.

// The __set__() call returns a function that, when called, resets the

// overwritten function back to its original.

var reset = count.__set__('_countStart', function(filename) {

logFileArgument = filename;

return 2;

});

count.countStart({}, fakeResObject);

dataSent.should.eql({ numStart: 2 });

logFileArgument.should.equal(logFileName);

reset();

});

That’s a lot of preparation for a single test! This actually happens often, that the preparation for a unit test is significantly more code than the call and verification. It’s just part of testing.

In the above test, we still need the fake response object, but we don’t need to write files anymore.

This is a reasonable final state for our code. There is one more refactoring improvement that can be done.

Step 5

The last thing that bothers me is the _countStart function. This function does too much: it reads stuff from a file, and it counts stuff. Especially the counting part is a reasonably complex operation, and we’d like to test that separately.

Let’s split it into two parts.

// count.spec.js modifications

function _countStart(filename) {
  var data = _readFile(filename);
  return _countMatchingLinesInString(data, /server started/);
}

function _readFile(filename) {
  return fs.readFileSync(filename).toString();
}

function _countMatchingLinesInString(string, regexp) {
  return string.split(/\r\n|\r|\n/)
    .filter(function(line) { return regexp.test(line); })
    .length;
}

// count.spec.js modifications

function _countStart(filename) {

var data = _readFile(filename);

return _countMatchingLinesInString(data, /server started/);

}

function _readFile(filename) {

return fs.readFileSync(filename).toString();

}

function _countMatchingLinesInString(string, regexp) {

return string.split(/\r\n|\r|\n/)

.filter(function(line) { return regexp.test(line); })

.length;

}

There. Now it’s much easier to test the matching function.

// conut.spec.js part

  describe('_countMatchingLinesInString', function() {
    it('should count the number of lines that match in a string', function() {
      var _countMatchingLinesInString = count.__get__('_countMatchingLinesInString');

      var string = 'blah server started blah\n' +
                   'this line should not match\n' +
                   'server started server started should count as one\n';
      var regexp = /server started/;
      var num = _countMatchingLinesInString(string, regexp);
      num.should.equal(2);
    });
  });

// conut.spec.js part

describe('_countMatchingLinesInString', function() {

it('should count the number of lines that match in a string', function() {

var _countMatchingLinesInString = count.__get__('_countMatchingLinesInString');

var string = 'blah server started blah\n' +

'this line should not match\n' +

'server started server started should count as one\n';

var regexp = /server started/;

var num = _countMatchingLinesInString(string, regexp);

num.should.equal(2);

});

The test for _readFile is also simple.

// conut.spec.js part

  describe('_readFile', function() {
    var logFileName = __dirname + '/unit-test-file.log';
    function cleanupTestFile() {
      if (fs.existsSync(logFileName)) {
        fs.unlinkSync(logFileName);
      }
    }
    beforeEach(cleanupTestFile);
    afterEach(cleanupTestFile);

    it('should read the log file', function() {
      var _readFile = count.__get__('_readFile');

      fs.appendFileSync(logFileName, 'line one\n');
      fs.appendFileSync(logFileName, 'line two\n');

      var data = _readFile(logFileName);
      data.should.equal('line one\nline two\n');
    });
  });

// conut.spec.js part

describe('_readFile', function() {

var logFileName = __dirname + '/unit-test-file.log';

function cleanupTestFile() {

if (fs.existsSync(logFileName)) {

fs.unlinkSync(logFileName);

}

beforeEach(cleanupTestFile);

afterEach(cleanupTestFile);

it('should read the log file', function() {

var _readFile = count.__get__('_readFile');

fs.appendFileSync(logFileName, 'line one\n');

fs.appendFileSync(logFileName, 'line two\n');

var data = _readFile(logFileName);

data.should.equal('line one\nline two\n');

});

Looking at these four functions, we can notice a difference between the two pairs. _readFile and _countMatchingLinesInString are functions that do actual work. Let’s call them worker functions. The functions countStart and _countStart don’t do any work, but they link worker functions together. Let’s call these linker functions.

To test a linker function, all you need to do is to verify that it calls the right worker functions in the right order, with the right arguments. This can be done by mocking the worker functions; there is no need to call the actual worker functions. For example, for _countStart :

// conut.spec.js part

  describe('_countStart', function() {
    it('should call _readFile and _countMatchingLinesInString', function() {
      var _readFileArg, _countArg1, _countArg2;
      var fileContents = '123 server started\n456 server started server started\nthird line';
      var reset1 = count.__set__('_readFile', function(arg) {
        _readFileArg = arg;
        return fileContents;
      });
      var reset2 = count.__set__('_countMatchingLinesInString', function(arg1, arg2) {
        _countArg1 = arg1;
        _countArg2 = arg2;
      });

      var filename = 'testfile.log';

      var _countStart = count.__get__('_countStart');
      _countStart(filename);

      _readFileArg.should.eql(filename);
      _countArg1.should.eql(fileContents);
      _countArg2.should.eql(/server started/);
      reset1();
      reset2();
    });
  });

// conut.spec.js part

describe('_countStart', function() {

it('should call _readFile and _countMatchingLinesInString', function() {

var _readFileArg, _countArg1, _countArg2;

var fileContents = '123 server started\n456 server started server started\nthird line';

var reset1 = count.__set__('_readFile', function(arg) {

_readFileArg = arg;

return fileContents;

});

var reset2 = count.__set__('_countMatchingLinesInString', function(arg1, arg2) {

_countArg1 = arg1;

_countArg2 = arg2;

});

var filename = 'testfile.log';

var _countStart = count.__get__('_countStart');

_countStart(filename);

_readFileArg.should.eql(filename);

_countArg1.should.eql(fileContents);

_countArg2.should.eql(/server started/);

reset1();

reset2();

});

For this specific example, I’m not sure whether step 5 is overkill. It might be. I found it important to show you though, because for more complex situations, the separation into worker functions and linker functions can make your life much easier.

Conclusions

Even for a very simple server that only does one thing, writing unit tests will make you think about and improve the design of your code. If a function or module is hard to test, it is often an indication of a problem with the design.

When testing, keep in mind dependency injection and the difference between worker functions and linker functions. Also think about which parts of the code have already been tested elsewhere, so you know when it’s safe to mock or monkey patch that code. This will help you to restructure your code to make it easier to test – and hopefully also easier to reuse and maintain.

Automated software testing part 3: writing tests, and refactoring

Step 1

Step 2

Step 3

Step 4

Step 5

Conclusions

Leave a Reply Cancel reply

Recent Posts

Archives

Categories

Meta