How I fixed Node.js again

As usual, I was browsing the node.js issues page when I noticed #4467. The project owner jasnell had identified a small script that unexpectedly crashed with the message console.error is not a function. Huh? Last I checked, console.error is totally a function. I had to get to the bottom of this one. It turned out to be quite a rabbit hole, taking me through some of node.js’s most important features. Hold on to your hat!

Events

The failing script used the events module, which is node.js’s implementation of event-driven programming. Events are easy to understand: you start with an object called an EventEmitter, which the events module provides. You can add event listeners to an EventEmitter with the on method. An event listener is a function that gets called when the EventEmitter emits a particular event, identified by a string. Then when the EventEmitter calls its emit method on an event string, all the listeners on that event get called. Here’s a simple example:

// events-example.js
var events = require('events');

// get an event emitter
var e = new events.EventEmitter();

// add some listeners on the 'hello' event
e.on('hello', function() { console.log('first listener'); });
e.on('hello', function() { console.log('second listener'); });

// emit the 'hello' event -- this will trigger the listeners
e.emit('hello');

Running it:

$ node ./events-example.js
first listener
second listener

Bam! Pretty cool stuff. Events are a big part of programming in node.js: for instance, you use them to define what a server does when a request comes in, since each request triggers a 'connection' event.

Internally, the EventEmitter keeps track of an object called this.events that maps event names to arrays of event handlers. When a program calls the on method with an event name and event handler, the EventEmitter adds the handler to the array for that event name. Then the emit method just calls each handler in the EventEmitter’s array for the given event name.

EventEmitters have one more feature we’ll need to make friends with: the maxListeners property. If you try to add more than maxListeners to a single event, then the EventEmitter will log warning: possible EventEmitter memory leak detected. (maxListeners is a bit of a misnomer as the EventEmitter still adds the listener and will call it when the event is triggered, so it’s not a hard maximum.) The default maxListeners per event per EventEmitter is 10, so you can see maxListeners in action by adding 9 more calls to e.on('hello') in my script above.

You can modify maxListeners for a specific EventEmitter with the setMaxListeners method, or you can change the default from 10 by setting the defaultMaxListeners property on the events module itself. The buggy script in question did just that. Without further ado, here it is:

var events = require('events');
events.defaultMaxListeners = 1;

var e = new events.EventEmitter();
e.on('hello', function() {});
e.on('hello', function() {});

That’s it! Running it with Node 5.4, we get:

$ node broken-script.js 
events.js:235
        console.error('(node) warning: possible EventEmitter memory ' +
                ^

TypeError: console.error is not a function
    at process.addListener (events.js:235:17)
    at process.stderr (node.js:685:17)
    at console.js:93:53
    at NativeModule.compile (node.js:990:5)
    at Function.NativeModule.require (node.js:935:18)
    at node.js:233:27
    at EventEmitter.addListener (events.js:235:9)
    at Object.<anonymous> (/Users/davidgalbraith/node/broken-script.js:6:23)
    at Module._compile (module.js:397:26)
    at Object.Module._extensions..js (module.js:404:10)

Ouch. Let’s figure out what went wrong.

The search

By following the stack trace in the exception, I ended up in the addListener method of EventEmitter. addListener is an alias for on, so it adds a given event handler to the EventEmitter’s list for a given event name. Also, it checks for a maxListeners violation with this code:

if (!existing.warned) {
  m = $getMaxListeners(this);
  if (m && m > 0 && existing.length > m) {
    existing.warned = true;
    if (!internalUtil)
      internalUtil = require('internal/util');

    internalUtil.error('warning: possible EventEmitter memory ' +
                       'leak detected. %d %s listeners added. ' + 
                       'Use emitter.setMaxListeners() to increase limit.',
                       existing.length, type);
    console.trace();
  }
}

existing is the array of listeners. internalUtil.error is a wrapper around console.error. The stack trace says that internalUtil.error‘s call to console.error fails because console.error is not a function.

I wanted to find out what the console object looked like at the time of the call to internalUtil.error. I started with this:

if (!existing.warned) {
  m = $getMaxListeners(this);
  if (m && m > 0 && existing.length > m) {
    console.log(console);
    // rest of code as before

But that just failed with the message console.log is not a function! I was in a bind: how could I debug the console if I couldn’t use the console to debug? Eventually I came up with a little hack: I declared a global variable called brokenConsole, then rewrote the snippet like this:

if (!existing.warned) {
  m = $getMaxListeners(this);
  if (m && m > 0 && existing.length > m) {
    if (!console.log) {
      brokenConsole = console;
      return;
    }
    // rest of code as before

I added a method getBrokenConsole to the EventEmitter class that just returned the global brokenConsole object, and I added the line

console.log('broken console:', events.getBrokenConsole());

to the end of my test script. I knew, or at least strongly hoped, that I’d be able to safely use console from my own script. Indeed, with these changes, the program ran without crashing and logged broken console: {}. The console had been an empty object!

How could console be empty? I had to find how console gets set up and accessed. I finally tracked it down at the very heart of Node: the actual Javascript file called node.js. There I found a call during Node’s initialization to startup.globalConsole(), a function that looks like this:

startup.globalConsole = function() {
  global.__defineGetter__('console', function() {
    return NativeModule.require('console');
  });
};

Let’s break that down.

global and require

Every node.js program has access to an object called global that contains information about the program. You can see it by running node -e 'console.log(global)' on the command line. All global variable references in node.js are actually property accesses on the global object. Check it out:

$ node
 > global.x
 undefined
 > var x = 1;
 undefined
 > global.x
 1
 > global.y = 2;
 2
 > y
 2

So when a program refers to console, it is actually referring to the console property of the global object. The startup.globalConsole function sets this property, defining what a reference to it returns: something called NativeModule.require('console'). Elsewhere in the node.js file, I found the definition of NativeModule.require. Here are the relevant parts:

NativeModule.require = function(id) {
  var cached = NativeModule.getCached(id);
  if (cached) {
    return cached.exports;
  }

  var nativeModule = new NativeModule(id);

  nativeModule.cache();
  nativeModule.compile();

  return nativeModule.exports;
};

To keep the startup process as lean as possible, Node doesn’t finish setting up console until the first time it is referenced. At that time, NativeModule.require creates a new NativeModule object, caches it, and finishes setting it up by calling compile(). Any references to console after the first receive the cached object, so Node doesn’t have to call compile() again. Let’s see this compile method for ourselves:

NativeModule.prototype.compile = function() {
  var source = NativeModule.getSource(this.id);
  source = NativeModule.wrap(source);

  var fn = runInThisContext(source, {
    filename: this.filename,
    lineOffset: 0
  });
  fn(this.exports, NativeModule.require, this, this.filename);

  this.loaded = true;
};

NativeModule.wrap = function(script) {
  return NativeModule.wrapper[0] + script + NativeModule.wrapper[1];
};

NativeModule.wrapper = [
  '(function (exports, require, module, __filename, __dirname) { ',
  '\n});'
];

Now this is a very deep, very important bit of code, so let’s read it closely. NativeModule.getSource returns the source code for the module as a string. For console, that’s the contents of the file console.js.

Then NativeModule.wrap adds a line to the beginning and end of the source code. These lines wrap the source in a function that takes exports, require, module, __filename, and __dirname arguments. Finally, runInThisContext is essentially the same as eval: it turns this function-wrapped source code string into an actual Javascript function.

We call this actual Javascript function passing NativeModule.require as the require argument and the caller itself as the module argument. When console.js requires another file, that’s actually a recursive call to NativeModule.require. And when it modifies module.exports, it is actually modifying the exports property on the NativeModule object that is calling compile(), the same object that is stored in NativeModule’s cache and returned by NativeModule.require.

… so I put a require in your require so you can load while you load

So that’s all very smart, but let’s see how it caused our program to crash. Take another look at the require function: note that it caches the module before calling compile() on it. Until compile() completes, the module’s exports is an empty object.

What happens if a function refers to console during the execution of console‘s compile()? Well, by the getter defined in globalConsole(), this returns the result of a call to NativeModule.require('console'). The line var cached = NativeModule.getCached(id); now finds the cached entry for 'console', so it returns its exports. But console‘s compilation isn’t finished yet! So the cached exports is still an empty object, so this empty object is returned as the value of console.

That all means that if a function calls console.error() during console’s compile(), it crashes with the error console.error is not a function. I had a hunch this was what was going on. To confirm my suspicions, I had to trace through console.js for any chain of reference that might end up referring back to console. I finally found it in the second-to-last line of the file:

module.exports = new Console(process.stdout, process.stderr);

Looks harmless! Is not harmless. Check out the getter functions for process.stdout and process.stderr, defined in the node.js file (edited for brevity):

process.__defineGetter__('stdout', function() {
  if (stdout) return stdout;
  stdout = createWritableStdioStream(1);
  if (stdout.isTTY) {
    process.on('SIGWINCH', function() {
      stdout._refreshSize();
    });
  }
  
  return stdout;
});

process.__defineGetter__('stderr', function() {
  if (stderr) return stderr;
  stderr = createWritableStdioStream(2);
  if (stderr.isTTY) {
    process.on('SIGWINCH', function() {
      stderr._refreshSize();
    });
  }
 
  return stderr;
});

As with the global console, process.stdout and process.stderr are initialized only when referenced. This line in console.js is the first reference in our program to stdout and stderr, so it triggers their initialization.

stdout.isTTY and stderr.isTTY are true when running a script from a file, so each getter adds a SIGWINCH event handler to process. But wait! We already set the defaultMaxListeners property to 1. The addition of these two SIGWINCH event handlers causes another warning about going over the maxListeners threshold.

Remember, we added those listeners during the compilation of the global console, after NativeModule.require has cached the empty object but before it has filled in the properties of that object with console‘s functions. So the code that attempts to log this second warning receives the cached empty object and fails with console.error is not a function. Mystery solved!

The Fix

Now that I knew what was going on, I had to get it working right. My first instinct was to always compile the global console during node.js’s setup phase, so it would always be ready at any point in a program. That would fix this bug and any like it. But I thought about it more, and it seemed like the bug was too rare to warrant such a major change: all node.js programs would have to pay the extra startup cost of compiling the global console up front, just so the fringe programs that set events.defaultMaxListeners to 1 wouldn’t crash. Not worth it!

Then I thought to change the addListener logging logic, making it check if console.error exists before calling it. This had the advantage of not impacting startup time while still keeping the program from crashing. But it had the disadvantage that any warnings that occurred while console was not yet compiled would be silently ignored. Ideally, console would always be ready to log these warnings when they occur.

So I came to my final solution: I implemented a setter for the EventEmitter.defaultMaxListeners property. Whenever a program sets EventEmitter.defaultMaxListeners, my setter is called. Here’s how it looks:

var defaultMaxListeners = 10;

Object.defineProperty(EventEmitter, 'defaultMaxListeners', {
  enumerable: true,
  get: function() {
    return defaultMaxListeners;
  },
  set: function(arg) {
    console;
    defaultMaxListeners = arg;
  }
});

The set function contains the apparently-inert line console;, which only has the invisible effect of compiling console if it does not exist. With this change to the EventEmitter class, our program no longer crashes with "console.error is not a function", and it logs the expected warning. I pushed a commit with this change, opened a pull request, and all agreed it was worthy. Just like that, I’d fixed node.js again!

A footnote

Attentive fans of How I Fixed libuv will remember this line, which I never explained there:

process.stdout; // this line seems to do nothing, but the segmentation fault only happens when it's present

Now we know why this was necessary for that segmentation fault! The reference to the process variable causes process to be compiled, which adds the SIGWINCH event handlers we saw earlier. It turns out that if there are no listeners for the SIGWINCH event, then resizing the terminal window doesn’t interrupt a call to read(). Since the read doesn’t get interrupted, the faulty EINTR logic doesn’t kick in, and the program doesn’t crash.