I was working on my latest module for node, latest, when I encountered a problem. While testing, I noticed output being written to the terminal that I wasn’t generating. This means that some module had the audacity to write directly to the terminal… bad.

My project was only including the npm module, however the npm module included its own handful of other modules, and they included their own modules, and so-on. If I were to look through the source myself to try and find what was outputting to the terminal it would have taken forever, trying to trace what function was calling what. Instead, I decided to override the stdout streams write function, to stack trace when invoked. This means that any function that writes to stdout will cause a stack trace to be printed to the screen.

Example

Imagine a script that looks like this

require('./1');
require('./2');
require('./3');
console.log('done');

very simple. It includes 3 modules, and then prints “done”. Let’s look at the output it generates.

undefined
done

What? why does it print “undefined” before it prints “done”? One of the included modules is taking it upon itself to write directly to the terminal. Without knowing where to look I might make the mistake of trying to hunt down the function myself, tracing code paths in my head, trying to make sense of someone else’s code. Instead, let’s cut it off at the source, and force every write to dump a stack trace.

All I have to do is add a bit of code to the top of the example file

var a = process.stdout.write;
process.stdout.write = function() {
  console.trace();
  a.apply(this, arguments);
};

require('./1');
require('./2');
require('./3');
console.log('done');

It might look confusing what is happening here, but it’s actually very simple. I first declare a variable a, and set it to what process.stdout.write is set to (a function). Then, I redefine process.stdout.write to be a function that first dumps a trace, and then calls the real/original write function. It might look recursive, but this is possible in javascript thanks to closures.

Now, when I run this I see

Trace
    at WriteStream.process.stdout.write (/Users/dave/temp/streamsnoop/main.js:3:13)
    at Object.exports.log (console.js:25:18)
    at Object.<anonymous> (/Users/dave/temp/streamsnoop/2.js:1:71)
    at Module._compile (module.js:449:26)
    at Object.Module._extensions..js (module.js:467:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Module.require (module.js:362:17)
    at require (module.js:378:17)
    at Object.<anonymous> (/Users/dave/temp/streamsnoop/main.js:8:1)
undefined
Trace
    at WriteStream.process.stdout.write (/Users/dave/temp/streamsnoop/main.js:3:13)
    at Object.exports.log (console.js:25:18)
    at Object.<anonymous> (/Users/dave/temp/streamsnoop/main.js:11:9)
    at Module._compile (module.js:449:26)
    at Object.Module._extensions..js (module.js:467:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Module.runMain (module.js:492:10)
    at process.startup.processNextTick.process._tickCallback (node.js:244:9)
done

There are 2 traces, 1 from “undefined” being printed to the screen, and the other where I print “done”. The first trace is the most telling, if we follow it backwards we will find the culprit. The first line of the trace says main.js:3:13, which is telling us the line of code where the trace was triggered. The next line shows console.js, because we called trace manually. Moving onto the third line we see 2.js:1:71, which tells us exactly where the problem is.

The module 2.js is writing to stdout on line 1. If we look into this file we see

console.log(undefined);

and sure enough, that’s the problem. Overriding the process.stdout.write function has made it possible to find this issue without having to dig through (potentially) a lot of files manually.

You can read the abridged version in this github gist