Sinon spy.called no working

Question

Background

I have a small server that receives data from a machine. Every time I receive a message I call a function in a dispatcher object that simply console.logs everything it receives.

Problem

The code works well as I can see the console.logs in the console, but Sinon spy.called doesn't work. It is always false no matter how many times I call dispatcher.onMessage.

Code

server.js

const eventDispatcher = {
    onMessage: console.log,
};

const server = (dispatcher = eventDispatcher) => {


    //this gets called everytime the server receives a message
    const onData = data => {

        //Process data
        //....
        dispatcher.onMessage(data);
    };


    const getDispatcher = () => dispatcher;

    return Object.freeze({
        getDispatcher
    });
};

test.js

describe("message sender", () => {

    const myServer = serverFactory();


    it("should send information to server", () => {
        dummyMachine.socket.write("Hello World!
");

        const dataSpy = sinon.spy(myServer.getDispatcher(), "onMessage");
        expect(dataSpy.called).to.be.true; //always fails!
    });

});

Research

After reading similar posts I believe this happens due to some layer of indirection, as pointed in:

Sinon Spy is not called if the spied method is called indirectly

And should be fixed via using this:

Sinon.spy on a method is not invoked

However, looking at my code I really can't get what I am missing.

Question

What am I doing wrong?

MCVE

Directory Structure

 Project_Folder
 |____package.json
 |____server.js
 |____test
      |____ dummyMachine_spec.js

package.json

{
  "name": "sinon-question",
  "version": "1.0.0",
  "description": "MCVE about a dummy machine connecting to a server for StackOverflow",
  "main": "server.js",
  "scripts": {
    "test": "NODE_ENV=test mocha --reporter spec --slow 5000 --timeout 5000 test/*_spec.js || true"
  },
  "author": "Pedro Miguel P. S. Martins",
  "license": "ISC",
  "devDependencies": {
    "chai": "^3.5.0",
    "mocha": "^3.3.0",
    "sinon": "^2.2.0"
  },
  "dependencies": {
    "net": "^1.0.2"
  }
}

server.js

"use strict";

const net = require("net");

const eventDispatcher = {
    onMessage: console.log,
};

const server = (dispatcher = eventDispatcher) => {

    let serverSocket;

    const onData = data => {
        //Process data
        dispatcher.onMessage(`I am server and I got ${data}`);
    };

    const start = (connectOpts) => {
        return new Promise(fulfil => {
            serverSocket = net.createConnection(connectOpts, () => {
                serverSocket.on("data", onData);   
                fulfil();
            });
        });
    };

    const stop = () => serverSocket.destroy();

    const getDispatcher = () => dispatcher;

    return Object.freeze({
        start,
        stop,
        getDispatcher
    });
};

module.exports = server;

test/dummyMachine.js

"use strict";


const chai = require("chai"),
    expect = chai.expect;

const sinon = require("sinon");
const net = require("net");
const serverFactory = require("../server.js");

describe("Dummy Machine", () => {

    const dummyMachine = {
        IP: "localhost",
        port: 4002,
        server: undefined,
        socket: undefined
    };

    const server = serverFactory();

    before("Sets up dummyReader and server", done => {

        dummyMachine.server = net.createServer(undefined, socket => {
            dummyMachine.socket = socket;
        });

        dummyMachine.server.listen(
            dummyMachine.port,
            dummyMachine.IP,
            undefined,
            () => {
                server.start({
                    host: "localhost",
                    port: 4002
                })
                .then(done);
            }
        );
    });

    after("Kills dummyReader and server", () => {
        server.stop();
        dummyMachine.server.close();
    });

    it("should connect to server", done => {
        dummyMachine.server.getConnections((err, count) => {
            expect(err).to.be.null;
            expect(count).to.eql(1);
            done();
        });

    });

    it("should send information to server", () => {
        dummyMachine.socket.write("Hello World
");

        const dataSpy = sinon.spy(server.getDispatcher(), "onMessage");
        expect(dataSpy.called).to.be.true; //WORK DAAMN YOU!
    });
});

Instructions for MCVE

Download the files and create the directory structure indicated.
Enter project folder and type npm install on a terminal
Type npm test

The first test should pass, meaning a connection is in fact being made.

The second test will fail, even though you get the console log, proving that onMessage was called.

robertklep · Accepted Answer

The main problem is that it's not enough to just spy on onMessage, because your test will never find out when it got called exactly (because stream events are asynchronously delivered).

You can use a hack using setTimeout(), and check and see if it got called some time after sending a message to the server, but that's not ideal.

Instead, you can replace onMessage with a function that will get called instead, and from that function, you can test and see if it got called with the correct arguments, etc.

Sinon provides stubs which can be used for this:

it("should send information to server", done => {
  const stub = sinon.stub(server.getDispatcher(), 'onMessage').callsFake(data => {
    stub.restore();
    expect(data).to.equal('I am server and I got Hello World
');
    done();
  });
  dummyMachine.socket.write("Hello World
");
});

Instead of the original onMessage, it will call the "fake function" that you provide. There, the stub is restored (which means that onMessage is restored to its original), and you can check and see if it got called with the correct argument.

Because the test is asynchronous, it's using done.

There are a few things to consider:

You can't easily detect if, because of a programming error, onMessage doesn't get called at all. When that happens, after a few seconds, Mocha will timeout your test, causing it to fail.
If that happens, the stub won't be restored to its original and any subsequent tests that try to stub onMessage will fail because the method is already stubbed (usually, you work around this by creating the stub in an onBeforeEach and restore it in an onAfterEach)
This solution won't test the inner workings of onMessage, because it's being replaced. It only tests if it gets called, and with the correct argument (however, it's better, and easier, to test onMessage separately, by directly calling it with various arguments from your test cases).