Thursday, June 2, 2011

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

No comments:

Post a Comment