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.
Imagine a script that looks like this
very simple. It includes 3 modules, and then prints “done”. Let’s look at the output it generates.
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
It might look confusing what is happening here, but it’s actually very simple. I first declare a
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
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.
2.js is writing to stdout on line 1. If we look into this file we see
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