Debugging Node.js SSL Negotiation

‹prev | My Chain | next›

Up today, a bit of node-spdy-related administravia. For the most part, I have very much enjoyed working with node-spdy. It supports a large subset of the SPDY protocol (draft 2) and is quite approachable code. My biggest obstacle that I have hit while working with it is hitting errors like this:

➜  node-spdy git:(reply-compression) ✗ node ./test/spdy-server.js
TLS NPN Server is running on port : 8081

node.js:183
        throw e; // process.nextTick error, or 'error' event on first tick
        ^
TypeError: Object [object Object] has no method 'destroy'
    at CleartextStream.onclose (stream.js:92:10)
    at CleartextStream.emit (events.js:81:20)
    at Array.<anonymous> (tls.js:640:22)
    at EventEmitter._tickCallback (node.js:175:26)

Ah the joys of functional code. This error looks to be coming from deep within the bowels of node.js itself, but it is clearly caused by something in node-spdy.

Rather than pollute the node.js source with debugging statements, I fall back to my old favorite, process.on('uncaughtException') to give me the change to inspect the failure more closely:

// Don't crash on errors
process.on('uncaughtException', function (err) {
  console.log('Caught uncaughtException: ' + err.stack);
});

That only prevents the crash, printing out the same stack trace that I have already seen. Thankfully there are a few more options available on the err object passed into the process.on callback:

// Don't crash on errors
process.on('uncaughtException', function (err) {
  for (var prop in err) {
    console.log(prop);
  }
});

This logs the following properties:

stack
arguments
type
message
name

I already know what stack includes. Logging the others shows:

arguments: destroy,[object Object]
type: undefined_method
message: Object [object Object] has no method 'destroy'
name: TypeError

So it seems that type, message, and type are pretty useless (unless I am trying to pretty-print a stacktrace). The arguments looks to be of interest.

So I check out err.arguments[0] in process.on:

// Don't crash on errors
process.on('uncaughtException', function (err) {
  console.log(err.arguments[1].constructor.toString());
});

I do not get a nice, named constructor, but instead find:

function (zlib) {
  Stream.call(this);

  this.writable = this.readable = true;

  this.zlib = zlib;
  this.buffers = [];
}

Fortunately, that is enough information to find the object in question. I find that constructor in Parser:

var Parser = exports.Parser = function(zlib) {
  Stream.call(this);

  this.writable = this.readable = true;

  this.zlib = zlib;
  this.buffers = [];
};

So how does a parser object end up where a stream is expected?

Caught uncaughtException: TypeError: Object [object Object] has no method 'destroy'
    at CleartextStream.onclose (stream.js:92:10)
    at CleartextStream.emit (events.js:81:20)
    at Array.<anonymous> (tls.js:640:22)
    at EventEmitter._tickCallback (node.js:175:26)

I am running node installed from github source, I git pull, make and make install to get the latest changes. That only succeeds in changing line numbers in the stacktrace:

Caught uncaughtException: TypeError: Object [object Object] has no method 'destroy'
    at CleartextStream.onclose (stream.js:92:10)
    at CleartextStream.emit (events.js:81:20)
    at Array.<anonymous> (tls.js:654:22)
    at EventEmitter._tickCallback (node.js:175:26)

After some code spelunking, it appears that something is going wrong with the SSL negotiation. The portion of the stacktrace in the TLS module is inside a secure-pair destroy. I will investigate that a bit more tomorrow.

But first, I check out the SSL negotiation with Wireshark.

The client hello of a successful request:




Looks identical to the client hello of tonight's request:



A good server handshake:



Looks very different from the bad server handshake:



I am unsure why the server handshake is so different when the client hello is identical, but different it is.

Furthermore, a successful request includes a server certificate:



Whereas the bad request ends with a Change Cipher Spec:



I find it hard to believe that the server is behaving differently without some difference on the client side, so I think I will pick back up examining the client hello in a bit more detail tomorrow.

SPDYnode-spdy

Day #37