Sometimes There is No Substitute for Debugger

‹prev | My Chain | next›

Up tonight, I'd like to get back in the swing of express-spdy things by working on the only outstanding issue in the project's github tracker.

I think it would be fairly easy to just "fix" that issue, but I would like to take this opportunity to actually start testing express-spdy. I have been in the mode of getting to work against Chrome rather than BDDing it. I have yet to even take some time to accurately describe how it ought to behave. Now is a good time to get started on that.

I will use the very nice vows.js testing framework for this. I know that express.js proper likes to use espresso for testing, but I am more familiar with vows.

First up in my test, I have a lot of requiring to do:

var vows = require('vows'),
assert = require('assert'),
express = require('..'), // express-spdy
spdy = require('spdy'),
fs = require('fs'),
tls = require('tls');

I need vows and assert for testing. The request are required for establishing and configuring clients and servers for the test.

I copy a few options from the node-spdy testing framework:

// Common options

var PORT = 23456;

var options = {
key: fs.readFileSync(__dirname + '/../node_modules/spdy/keys/spdy-key.pem'),
cert: fs.readFileSync(__dirname + '/../node_modules/spdy/keys/spdy-cert.pem'),
ca: fs.readFileSync(__dirname + '/../node_modules/spdy/keys/spdy-csr.pem'),
npnProtocols: ['spdy/2'],
debug: true
};

With that, I can establish a test express-spdy server:

// Server

var app = express.createServer(options);

app.get('/', function(req, res){
res.send('wahoo');
});

app.listen(PORT);

That server should reply with nothing more that the string "wahoo", which should be easy enough to test. But first, I need to craft a SPDY SYN_SESSION to be used to request data from the express-spdy server:

// Client

var zlib = spdy.createZLib();

var spdy_request = spdy.createControlFrame(zlib,
{ type: spdy.enums.SYN_STREAM, streamID: 1, flags: 0 },
{ version: 'HTTP/1.1', url: '/', method: 'GET' }
);

Lastly a vow topic that creates the connection and sends the response into the vows via the this.callback mechanism built into vows.js:

vows.describe('Express SPDY response').addBatch({
'spdy.createServer': {
topic: function() {
var connection = tls.connect(PORT, 'localhost', options, function(){});
connection.write(spdy_request, this.callback);
},
'foooo' : function() {
console.log("here")
}
}
})

For now, I am not actually testing anything in here. I am fine just making it to that console.log statement. Unfortunately, when I run my test, I am not coming close to reaching it:

➜  express-spdy git:(master) ✗ vows test/response-test.js

node.js:205
throw e; // process.nextTick error, or 'error' event on first tick
^
TypeError: Object

Bah! I am not getting any kind of back trace in there to tell me where things are going wrong. Debugging with console.log tells me that the error is somewhere inside createControlFrame:

var spdy_request = spdy.createControlFrame(zlib,
{ type: spdy.enums.SYN_STREAM, streamID: 1, flags: 0 },
{ version: 'HTTP/1.1', url: '/', method: 'GET' }
);

But where?

To answer that, I drop down to the node debugger:

➜  express-spdy git:(master) ✗ node debug test/response-test.js
debug> run
debugger listening on port 5858connecting... ok
breakpoint #1 in #<Object>.[anonymous](exports=#<Object>, require=function require(path) {
return self.require(path);
}, module=#<Module>, __filename=/home/cstrom/repos/express-spdy/test/response-test.js, __dirname=/home/cstrom/repos/express-spdy/test), /home/cstrom/repos/express-spdy/test/response-test.js:1
(function (exports, require, module, __filename, __dirname) { var vows = require('vows'),
^
debug> step
...
debug> s
break in nvsToBuffer(zlib=#<Object>, headers=#<Object>, nvs=#<Object>), /home/cstrom/repos/express-spdy/node_modules/spdy/lib/spdy/protocol.js:132
buff.writeUInt16(nvsCount, 0, 'big');

After stepping through much of the code, I eventually see that the cause is a call to writeUInt16. Dammit. I am using the wrong freaking version of node-spdy with node 0.5.5. Ah well, that's easy enough to fix. Tomorrow.


Day #120