Debugging double-callback bugs in node.js

One of the most frustrating things that happens in a large node.js application is a double callback bug. They’re usually simple mistakes that are super tricky to track down. You may have seen one and not recognized it as such. In Express, one manifestation is Error: Can't set headers after they are sent; another one I’ve seen is an EventEmitter with an error event handler registered with ee.once('error', handler) that crashes the process saying it has an unhandled error – the first callback fires the error handler, the second triggers another error and since it was bound with once, it crashes. Sometimes they’re heisenbugs, where one path through a race condition resolves successfully, but another will manifest a crash or strange behavior.

The causes can be simple – here’s one:

function readJsonAsync(cb) {
    fs.readFile('file.json', 'utf-8', function (err, data) {
        if (err) {
            cb(err);
        }

        cb(null, JSON.parse(data));
    });
}

Can you spot it?

The error callback doesn’t end the function.

function readJsonAsync(cb) {
    fs.readFile('file.json', 'utf-8', function (err, data) {
        if (err) {
            return cb(err);
        }

        cb(null, JSON.parse(data));
    });
}

This version works more acceptably if fs.readFile gives us an error. Now let’s consider what happens when there’s a JSON parse error: This crashes, since an exception thrown by JSON.parse will unwind up the stack back to fs.readFile‘s handler in the event loop, which has no try/catch and will crash your process with an uncaughtException. Let’s add an exception handler.

function readJsonAsync(cb) {
    fs.readFile('file.json', 'utf-8', function (err, data) {
        if (err) {
            return cb(err);
        }

        try {
            cb(null, JSON.parse(data));
        } catch (e) {
            cb(e);
        }
    });
}

Yay! That way if the JSON fails to parse, we’ll get the error in the callback. Nice and tidy, right?

Not so fast. What if cb throws an exception, like in this calling code:

readJsonAsync(function (err, json) {
    if (err) {
        return console.warn("Fail!", err);
    }

    console.log("Success! Got all kinds of excitement! Check this out!");
    console.log(json.exciting.thing.that.does.not.exist);
});

Whoops. That last line throws TypeError: Cannot read property 'thing' of undefined.

That goes back to the callback function and the try/catch block, and we call back again with the error. Our callback gets called twice – which isn’t so bad with things that don’t care like console.log and console.warn, but even then, the output is confusing:

Success! Got all kinds of excitement! Check this out!
Fail! TypeError: Cannot read property 'thing' of undefined

It both worked and didn’t work! That’d crash our program if something throws an exception for a double callback. It’ll eat the error and we’d wonder why our program was misbehaving if the thing we’re calling ignored second callbacks.

We’ve also made a tricky conundrum here. There’s a lot of ways to solve it, from the ignoring multiple callbacks like so: (this example uses the once module)

var once = require('once');

function readJsonAsync(cb) {
    cb = once(cb);
    fs.readFile('file.json', 'utf-8', function (err, data) {
        if (err) {
            return cb(err);
        }

        try {
            cb(null, JSON.parse(data));
        } catch (e) {
            cb(e);
        }
    });
}

to the crashing more obviously because we just don’t handle the exception, like so:

function readJsonAsync(cb) {
    fs.readFile('file.json', 'utf-8', function (err, data) {
        if (err) {
            return cb(err);
        }

        var parsed;
        try {
            parsed = JSON.parse(data);
        } catch (e) {
            return cb(e);
        }

        cb(null, parsed);
    });
}

or one where we use setImmediate (or more tidily, check out the dezalgo package or the async package’s async.ensureAsync):

function readJsonAsync(cb) {
    fs.readFile('file.json', 'utf-8', function (err, data) {
        if (err) {
            return cb(err);
        }

        try {
            var parsed = JSON.parse(data);
            setImmediate(function () {
                cb(null, parsed);
            });
        } catch (e) {
            setImmediate(function () {
                cb(e);
            });
        }
    });
}

This means that the caller of readJsonAsync is on their own to handle their exceptions. No warranties, if it breaks, they get to keep both pieces, et cetera. But there’s no double callbacks!

So this gets tricky when you have a whole chain of things – someone’s made a mistake in something “so simple it can’t go wrong!” like a readFile callback that parses JSON, but the double callback comes out miles away, in a callback to something in a callback to something in a callback to something in a callback that calls readJsonAsync. This isn’t an uncommon scenario – every Express middleware is a callback, every call to next calls another. Every composed callback-calling function is another layer. The distance can get pretty severe sometimes. This is one of the less-loved benefits of promises: errors are much more isolated there, and the error passing is much more explicit. I think it’s a more important point than a lot of things about promises. But that’s neither here nor there. What we’re asking is:

How do we debug doubled callbacks?!

My favorite way is to write a function that will track a double callback and log the stack trace of both paths. This is a bit like the once package, but with error logging.

Here’s a simple version.

function justOnceLogIfTwice(cb) {
    var last;
    return function () { // return a new function wrapping the old one.
        if (!last) {
            last = new Error(); // Save this for later in case we need it.
            cb.apply(this, arguments); // Call the original callback
        } else {
            var thisTime = new Error("Called twice!");
            console.warn("Callback called twice! The first time is", last.stack, "and the next time is", thisTime.stack);
            // optionally, we might crash the program here if we want to be loud about errors. Like so:
            setImmediate(function () {
                // This is an "async throw" -- it can only be caught by error domains or the `uncaughtException` event on `process`.
                throw thisTime;
            });
        }
    };
}

We can then wrap our callbacks in it:

function readJsonAsync(cb) {
    cb = justOnceLogIfTwice(cb);
    fs.readFile('file.json', 'utf-8', function (err, data) {
        if (err) {
            return cb(err);
        }

        try {
            cb(null, JSON.parse(data));
        } catch (e) {
            cb(e);
        }
    });
}

Now we just have to trigger the error, and we should get two stack traces, once with the success path, and once with the error path.

Other ways? Set breakpoints on the calls to cb. See what the program state is at each of them.

Try to make a reproduction case. Good luck: it’s hard.

Add once wrappers to callbacks until you find the problem. Move them deeper and deeper until you find the actual source.

Give extra scrutiny to non-obvious error paths. If you can’t spot where errors go, I’d bet money on finding part or all of the bug in there.

Add an async-tracking stack trace module like long-stack-trace or longjohn. They slow your program down and can change the behavior because of the tricks they do to get long traces, but they can be invaluable if they don’t disturb things too much.

Consider using this eslint rule to catch the simpler cases – it won’t catch all of them, but it’ll at least catch the missing return case.

Good luck!