When Flow Control Goes Wild in SPDY/3

‹prev | My Chain | next›

Last night, I witnessed SPDY flow control. And it was glorious.

Well that might be a stretch, but it was pretty cool. I sent a SPDY SETTINGS frame to Chrome indicating that the data transfer window was very low, which ensured that Chrome would use flow control. I then sent back the necessary WINDOW_UPDATE to Chrome as data was POSTed from browser to server, allowing data to flow.

Tonight, I would like to see what happens in the opposite direction. What happens when the data being sent from a spdy/3 server (flow control is new in spdy/3) is too large for the data window?

For that, I need a large image. One of the scanned documents from The SPDY Book should suffice:

➜  express-spdy-test  ls -lh public/images 
total 836K
-rw-r--r-- 1 chris chris 830K Apr 30 22:56 pipelining.jpg

I add the image to the homepage of my simple spdy-ized express.js, restart the server and load the page up:

That broken image icon is not the result of HTML-gone-wrong. At first, it starts to load, but quickly goes broken after that. Checking the SPDY tab of Chrome's chrome://net-internals, I see that the image is, indeed requested. Indeed, transfer of the data seems to start out OK:

SPDY_SESSION_SYN_STREAM
--> flags = 1
--> :host: localhost:3000
    :method: GET
    :path: /images/pipelining.jpg
    :scheme: https
    :version: HTTP/1.1
    accept: */*
    accept-charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
    accept-encoding: gzip,deflate,sdch
    accept-language: en-US,en;q=0.8
    cookie: [value was stripped]
    referer: https://localhost:3000/
    user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/536.9 (KHTML, like Gecko) Chrome/20.0.1115.1 Safari/536.9
--> id = 7
SPDY_SESSION_SYN_REPLY
--> flags = 0
--> :status: 200
    :version: HTTP/1.1
--> id = 7
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 1300
--> stream_id = 7
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 1300
--> stream_id = 7
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 1300
--> stream_id = 7
...

The browser ends up seeing 29 of those 1300 byte DATA frames before it issues a WINDOW_UPDATE:

...
SPDY_SESSION_SENT_WINDOW_UPDATE
--> delta = 37700
--> stream_id = 7
...

Theis WINDOW_UPDATE is informing the server that 37700 bytes, which happens to be all of the data sent so far (29 * 1300 = 37700), has been processed and that more data may been sent.

Currently, node-spdy is WINDOW_UPDATE ignorant, so these frames go quietly ignored:

Express server listening on port 3000 in development mode
Unknown type:  unknown: 9

The WINDOW_UPDATE from the browser is ignored and the server keeps right on sending data, which is what the browser wants anyway.

Another 31 data frames are sent, each sized 1300 bytes. There is also a stray 660 byte frame, for a grand total of 40960 bytes. And then Chrome issues another WINDOW_UPDATE indicating that all of the data received so far has been processed:

....
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 1300
--> stream_id = 7
SPDY_SESSION_SENT_WINDOW_UPDATE
--> delta = 40960
--> stream_id = 7
...

This is followed by another 25 full-sized frames and one 660 byte frame, along with a WINDOW_UPDATE for delta = 33160. The same pattern is repeated once more, resulting in another WINDOW_UPDATE for delta = 33160.

After each of these WINDOW_UPDATE frames, the internal data transfer window that the server should have is 64kb, the default data transfer window in SPDY. The server sends 33kb or so of data, the window goes down, then the browser signals that is has read all pending data and the window goes back to 64kb.

And then something interesting happens.

Not 29, 25, or 31 DATA frames are sent. This time, 60 full DATA frames are sent, plus two 660 sized DATA frames. This is a total of 79320 bytes that are sent from the server to the browser, which is well past the 64kb transfer window.

At this point, Chrome does the right thing by telling the server that something has gone wrong:

SPDY_SESSION_SEND_RST_STREAM
--> description = "Negative recv window size"
--> status = 1
--> stream_id = 7

Chrome is no longer listening, but node-spdy goes right on sending the data--to no avail. The result is a broken image. Actually, it is not so much broken as ignored.

My takeaway from this is that spdy/3 conversations had better be flow control aware otherwise there is going to be a lot of ignored data. So I will get started on that tomorrow.


Day #372

Real SPDY v3 WINDOW_UPDATE

‹prev | My Chain | next›

I ended yesterday in an argument with Chrome over SPDY version 3 WINDOW_UPDATE frames. I thought that sending them immediately after connection should impact the browser's data window. Chrome disagreed.

Upon further reading of the specification, it turns out that I may, in fact, have been mistaken. I have a hard time reading networking specifications sometimes, but I now think that WINDOW_UPDATE is only sent after too much data has already been received.

The scenario from the specification is that the window size is originally the default 64KB, but the recipient immediately replies on connection that it can only handle 16KB. Unlike what I did yesterday, the specification states that the recipient communicates this information with a SETTINGS frame, not a WINDOW_UPDATE. The sender has already sent along the default 64KB, so it now realizes that it has sent 48KB too much. Assuming the recipient does not terminate the session (which is a possibility), then the sender needs to wait for enough WINDOW_UPDATE frames to be sent back to add up to 48kb at which point data can again start flowing.

That seems like a hard scenario to establish when the server is the recipient. The form that I use to submit the data will already have established SETTINGS:

So a race condition of 64KB vs. 16KB seems hard to establish. Besides, I could be completely wrong about this whole thing (again).

So, instead, I specify an absurdly small window size, 1024 bytes, that the server can handle in the initial SETTINGS:

    // ...
    settings = new Buffer(28);

    settings.writeUInt32BE(0x80030004, 0, true); // Version and type
    settings.writeUInt32BE((4 + 8 + 8) & 0x00FFFFFF, 4, true); // length
    settings.writeUInt32BE(0x00000002, 8, true); // Count of entries

    settings.writeUInt32BE(0x01000004, 12, true); // Entry ID and Persist flag
    settings.writeUInt32BE(count, 16, true); // 100 Streams

    settings.writeUInt32BE(0x01000007, 20, true); // Entry ID and Persist flag
    settings.writeUInt32BE(1024 & 0x7fffffff, 24, true); // Window Size (Bytes)
    // ...

The SETTINGS frame goes out when the form is initially served so that, by the time the browser POSTs the form data to the server, both client and server should agree that 1024B is the window size.

Next, after every data frame is received, I lie to the browser that I have only processed half of the 1024B that it sent:

Parser.prototype.execute = function execute(state, data, callback) {
  if (state.type === 'frame-head') { /* ... */  }
  else if (state.type === 'frame-body') {
    var self = this;

    // Data frame
    if (!state.header.control) {
      this.connection.write(
        this.framer.windowUpdateFrame(state.header.id, 512)
      );

      return onFrame(null, {
        type: 'DATA',
        // ...
      });
    } else { /* ... */ }
  }
};

After the browser sends the 1024B window size that the browser and server agreed upon, its window size should be 0. In other words, it should pause until it gets back a WINDOW_UPDATE saying that all or part of the original 1024B has been processed. At this point, the browser's window size will equal what WINDOW_UPDATE says has been processed (the 512B that I lie about).

So I fire up the browser, fill out the form with well over 1024 characters and submit:

SPDY_SESSION_SYN_STREAM
--> flags = 0
--> :host: localhost:3000
    :method: POST
    :path: /cool
    :scheme: https
    :version: HTTP/1.1
    accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
    accept-charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
    accept-encoding: gzip,deflate,sdch
    accept-language: en-US,en;q=0.8
    cache-control: max-age=0
    content-length: 11747
    content-type: application/x-www-form-urlencoded
    origin: https://localhost:3000
    referer: https://localhost:3000/cool

And immediately after the opening SYN_STREAM, the browser sends a 1024B data packet:

SPDY_SESSION_SEND_DATA
--> flags = 0
--> size = 1024
--> stream_id = 9

And then it waits:

SPDY_SESSION_STALLED_ON_SEND_WINDOW
--> stream_id = 9

Meanwhile, the server processes the first data frame and lies that it had only processed 512B:

SPDY_SESSION_RECEIVED_WINDOW_UPDATE
--> delta = 512
--> stream_id = 9

At this point, the browser's internal data window is 512B, which it promptly sends along and then pauses until another WINDOW_UPDATE is sent:

SPDY_SESSION_SEND_DATA
--> flags = 0
--> size = 512
--> stream_id = 9
SPDY_SESSION_STALLED_ON_SEND_WINDOW
--> stream_id = 9

And, when the WINDOW_UPDATE is received, the cycle starts anew:

SPDY_SESSION_RECEIVED_WINDOW_UPDATE
--> delta = 512
--> stream_id = 9
SPDY_SESSION_SEND_DATA
--> flags = 0
--> size = 512
--> stream_id = 9
SPDY_SESSION_STALLED_ON_SEND_WINDOW
--> stream_id = 9

As you might imagine, it takes a number of round trips to complete the conversation. This example is intentionally contrived to see flow control in action. In real-life scenarios, a SPDY stream might pause a much larger window because of a slow DB write or unresponsive cluster node. The nice thing about the per-stream flow control in SPDY is that other streams can proceed like normal and regular TCP/IP flow control can also do its thing for then entire connection.

It would be nice for node-spdy to detect situations in which WINDOW_UPDATE frames are needed. Hard coding them like this is no solution. I also need to get the reverse case working. That is, if the server needs to send a 150KB image back to the browser, the server should wait until receiving WINDOW_UPDATEs. Grist for tomorrow, at least.


Day #371

Chrome and SPDY WINDOW_UPDATE

‹prev | My Chain | next›

Today, I am going to try to get my node-spdy-powered express.js site to force Chrome to honor the SPDY v3 WINDOW_UPDATE frame. I think it more likely that, in real life, the browser would send the server WINDOW_UPDATE packets to indicate that the server should slow down. I am unsure how to coerce Chrome into doing this, but I can send WINDOW_UPDATEs from node-spdy.

In fact, I was able to get node-spdy to send WINDOW_UPDATEs last night, but they had no effect. This was because the browser has no more data to send—it merely sent HTTP GET requests and was then done. The browser can send data—if it is POSTing a form. So I create a jade template to POST a form:

h1 Cool Form
p Enjoy our cool form

form#awesome(method="post")
  p
    input(type="text", name="title", value=title)

  p
    textarea(rows="10", cols="105", name="post")= post

  P
    input(type="submit", name="b", value="Cool!")

I then fill out the form with several hundred-character lines:

When I submit the form, however, I do not get the desired effect. The WINDOW_UPDATE is not being sent until after all of the form data has been sent:

...
SPDY_SESSION_SEND_DATA
--> flags = 0
--> size = 2852
--> stream_id = 1
SPDY_SESSION_SEND_DATA
--> flags = 0
--> size = 2852
--> stream_id = 1
SPDY_SESSION_SEND_DATA
--> flags = 0
--> size = 2852
--> stream_id = 1
SPDY_SESSION_SEND_DATA
--> flags = 1
--> size = 2004
--> stream_id = 1
SPDY_SESSION_RECV_SETTING
--> flags = 1
--> id = 4
--> value = 100
SPDY_SESSION_RECEIVED_WINDOW_UPDATE
--> delta = 8
--> stream_id = 1
SPDY_SESSION_SYN_REPLY
--> flags = 0
--> :status: 200
    :version: HTTP/1.1
--> id = 1
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 1300
--> stream_id = 1
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 1300
--> stream_id = 1
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 1300
--> stream_id = 1
...

In fact, Chrome is even getting the SETTINGS frame from node-spdy before it get the WINDOW_UPDATE frame, so I need to rearrange things a little.

This turns out not to be a simple matter of moving the WINDOW_UDPATE write before writing the SETTINGS frame:

this.parser.on('_framer', function(framer, header) {
    self.write(framer.windowUpdateFrame(header.id, 8));

    // Generate custom settings frame and send
    self.write(
      framer.maxStreamsFrame(options.maxStreams)
    );
  });

Well, it is a matter of doing that, but node's socket buffering is preventing that frame from being sent immediately, so I disable buffering with a call to socket.setNoDelay():

Connection.prototype.write = function write(data, encoding) {
  if (this.socket.writable) {
    this.socket.setNoDelay();
    return this.socket.write(data, encoding);
  }
};

That seems to do the trick.

I finally get:

...
SPDY_SESSION_RECEIVED_WINDOW_UPDATE
--> delta = 8
--> stream_id = 0
SPDY_SESSION_SEND_DATA
--> flags = 0
--> size = 2852
--> stream_id = 1
SPDY_SESSION_SEND_DATA
--> flags = 0
--> size = 2852
--> stream_id = 1
SPDY_SESSION_SEND_DATA
--> flags = 0
--> size = 2852
--> stream_id = 1
SPDY_SESSION_SEND_DATA
--> flags = 0
--> size = 2852
--> stream_id = 1
...

So Chrome seems to ignore WINDOW_UPDATE completely, unless I am missing something. Which is entirely possible.


Day #370

Getting Started with SPDY/3 Flow Control

‹prev | My Chain | next›

I had thought to mess about with spdy/2 and spdy/3 side-by-side some more, but I seem to have hit a snag. I disable spdy/3 in Chrome's about:flags:

But, when I reload my express.js site, powered by node-spdy, I am still using spdy/3:

That's what I get for mucking with experimental flags.

No matter how many times I try flipping that bit and restarting the browser, I continue to get spdy/3 connections. Hopefully that will get fixed in some future Chrome update.

Anyhow, flow control.

The SPDY v3 specifiction introduces flow control in the form of a WINDOW_UPDATE control frame.

In node-spdy parlance, this will look something like:

//
// ### function windowUpdateFrame (id)
// #### @id {Buffer} WindowUpdate ID
// Sends WINDOW_UPDATE frame
//
Framer.prototype.windowUpdateFrame = function windowUpdateFrame(id, delta) {
  var header = new Buffer(16);

  header.writeUInt32BE(0x80030009, 0, true); // Version and type
  header.writeUInt32BE(0x00000008, 4, true); // Length
  header.writeUInt32BE(id & 0x7fffffff, 8, true); // ID
  header.writeUInt32BE(delta & 0x7fffffff, 12, true); // delta

  return header;
};

The first four octets are version and type, the second 4 are the length (which is always 8 for WINDOW_UPDATE), the next four are for the stream ID, and the last four are the amount of data that can be sent beyond the initial window size (established in a SETTINGS frame). Actually, take my definition of delta with a grain of salt—I really do not have a firm grasp on the concept yet, which is why I am experimenting.

I think my first experiment will cause protocol errors. Even so, it seems the smallest step I can take. I am going to send a WINDOW_UPDATE immediately before my first SYN_REPLY. I think that this is wrong because the recipient of the data (the browser) should be sending WINDOW_UPDATEs per the spec, not the server. If I get a protocol error, then I can hope that I somewhat understand this and can build on it tomorrow. If I do not get a protocol error, then I can go back to the drawing board.

So, back in the server, I manually write a WINDOW_UPDATE after initializing the first SPDY stream:

function Connection(socket, pool, options) {
  // ...
  this.parser.on('frame', function (frame) {
    // ...
    // Create new stream
    if (frame.type === 'SYN_STREAM') {
      // ...
      if (frame.id == 1) {
        self.write(self.framer.windowUpdateFrame(frame.id, 8));
      }
      // ...
    }
    // ...
  }
  // ...
}

I specify a window size of 8 bytes. That is intentionally small so that it might have a noticeable effect should it be accepted.

So I restart the server, reload the page and...

SPDY_SESSION_SYN_STREAM
--> flags = 1
--> :host: localhost:3000
    :method: GET
    :path: /
    :scheme: https
    :version: HTTP/1.1
    ....
--> id = 1
SPDY_SESSION_RECV_SETTING
--> flags = 1
--> id = 4
--> value = 100
SPDY_SESSION_RECEIVED_WINDOW_UPDATE
--> delta = 8
--> stream_id = 1

The browser gets, and seemingly accepts, my WINDOW_UPDATE of a delta of 8 bytes. The rest of the SPDY conversation takes place as if this frame were not present. Specifically, the server issues a SYN_REPLY with more than 8 bytes in the DATA frame and no errors are raised:

SPDY_SESSION_SYN_REPLY
--> flags = 0
--> :status: 200
    :version: HTTP/1.1
--> id = 1
SPDY_SESSION_RECV_DATA 
--> flags = 0
--> size = 339
--> stream_id = 1
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 1

I am not surprised that the SYN_REPLY and subsequent DATA are unchanged—I have not done anything in the server to alter their behavior. I am also not surprised that the browser does not barf on receiving them—the WINDOW_UPDATE is sent by the recipient, but, in this case, the recipient is the browser which sent no WINDOW_UPDATE and should therefore be unaffected.

The only thing that surprises me is that the client accepted the WINDOW_UPDATE in the first place. Then again, SPDY conversations are bi-directional, so maybe that should not surprise me. Technically, the server could be a recipient of DATA (e.g. a POST body).

Satisfied that, if nothing else, my WINDOW_UPDATE is crafted well, I call it a night here. Tomorrow, I plan to start by POSTing data after a WINDOW_UPDATE to see if it has any effect. Then the fun begins...


Day #369

Branch for SPDY/3

‹prev | My Chain | next›

Yesterday I finally got a version 3 flavored SPDY conversation to take place. I had enabled spdy/3 in Chrome's about:flags the other day, but the struggled through conversion of node-spdy's version 2 implementation to account for incompatibilities between the two versions and then a dumb mistake in assembling the headers.

Today, I clean up.

First, I remove every console.log() statement. There were a lot.

Then I make sure that everything is still working. Stranger things have happened than everything breaking after removing console.log() statements. Thankfully that is not the case this time. I still have my spdy/3 session:

And, better still, no errors in the SPDY tab of about:net-internals:

....
SPDY_SESSION_SYN_REPLY
--> flags = 0
--> :status: 200
    :version: HTTP/1.1
--> id = 1
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 339
--> stream_id = 1
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 1
SPDY_SESSION_SYN_STREAM
--> flags = 1
--> :host: localhost:3000
    :method: GET
    :path: /stylesheets/style.css
    :scheme: https
    :version: HTTP/1.1
    accept: text/css,*/*;q=0.1
    accept-charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
    accept-encoding: gzip,deflate,sdch
    accept-language: en-US,en;q=0.8
    cache-control: no-cache
    cookie: [value was stripped]
    pragma: no-cache
    referer: https://localhost:3000/
    user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/536.9 (KHTML, like Gecko) Chrome/20.0.1115.1 Safari/536.9
--> id = 3
...

There is still much work to go, but this good enough to create a branch on the node-spdy repository.

The whole reason that I started down the spdy/3 road was to experiment with flow control. But there is at least one thing that I have to do before I move onto that. I need to re-enable spdy/2. Nearly all clients still use spdy/2, but right now I only have the spdy/3 zlib dictionary (used for blindingly fast header compression) hard-coded in lib/spdy/utils.js. I need to move that out of utils.js and into the protocol version definitions. I also need to dynamically select the appropriate dictionary at connection time.

Thankfully, the node-spdy module makes the value of the Next Protocol Negotation (an extension of SSL) available on the socket. So, when the zlib compression contexts are established on the connection, I can supply the protocol version:

function Connection(socket, pool, options) {
  process.EventEmitter.call(this);

  var self = this;

  this._closed = false;

  this.pool = pool;
  var pair = pool.get(socket.npnProtocol);

  this.deflate = pair.deflate;
  this.inflate = pair.inflate;
  // ...

The pool can then look up the dictionary using the appropriate SPDY version number:

Pool.prototype.get = function get(version, callback) {
  var version_number = version.split(/\//)[1],
      dictionary = spdy.protocol[version_number].dictionary;
  // ...

The dictionary itself is assigned to the protocol in the protocol's index.js (e.g. lib/spdy/protocol/v3/index.js):

lib/spdy/protocol/v3/index.jsvar v3;

// ...
module.exports = v3;

v3.dictionary = require('./dictionary').dictionary;

And the dictionary can be defined in dictionary.js as:

exports.dictionary = new Buffer([
 0x00, 0x00, 0x00, 0x07, 0x6f, 0x70, 0x74, 0x69,
 0x6f, 0x6e, 0x73, 0x00, 0x00, 0x00, 0x04, 0x68,
 0x65, 0x61, 0x64, 0x00, 0x00, 0x00, 0x04, 0x70,
        // ...
]);

(that is lifted directly from the spec)

With that, I have my SPDY version three connection working again. This time, however, the dictionary comes from the correct protocol version library. After doing the same for spdy/2, node-spdy is now capable of serving up both spdy/3 and spdy2 from the same server:

That is a good stopping point for now. Tomorrow, I will hopefully pick back up with flow control.

Day #368

Bad SPDY Headers

‹prev | My Chain | next›

I continue to struggle with implementing version 3 of the SPDY specification in node-spdy. I was finally able to get a response from inbound spdy/3 requests, but Chrome does not like the format of the response.

In fact, I have gotten to the point that Chrome actually recognizes that I am trying to speak spdy/3:

But, when I look at what Chrome thinks of the conversation, I see:

SPDY_SESSION_SEND_RST_STREAM
--> description = "Could not parse Spdy Control Frame Header."
--> status = 1
--> stream_id = 1

I have gone through the actual construction of the head a couple of times by hand and it looks OK. Of course, it's all writing bytes and lengths and things like that so it would be easy to make a mistake. Then there is the the Zlib compression...

I know that I have the Zlib inflation working because I can parse the inbound SPDY headers from Chrome. So a logical next step would be to attempt to parse the SPDY headers that I am generating. But before that, could it be as simple as missing those colon headers?

When I first parsed the inbound headers, I noticed some headers that started with colons:

headers: 
   { ':host': 'localhost:3000',
     ':method': 'GET',
     ':path': '/',
     ':scheme': 'https',
     ':version': 'HTTP/1.1',
     // ...
   }

I mistakenly thought something had gone wrong, but it turns out that they are part of the spec. And there are also colon headers that I am not including outbound: :status and :version. So I convert those headers over to be leading colon:

  // ...
  var dict = headersToDict(headers, function(headers) {
        headers[':status'] = code;
        headers[':version'] = 'HTTP/1.1';
      });

  this._synFrame('SYN_REPLY', id, null, dict, callback);

But unfortunately, Chrome still refuses to accept the headers.

So, it seems that I have to run through the internal parser after all. And it turns out that something is in fact not quite right with the header.

var spdy = require('spdy');
var inflate = spdy.utils.zwrap(spdy.utils.createInflate());
var b = new Buffer([0x38, 0xac, 0xe3, 0xc6, 0xa7, 0xc2, 0x02, 0xe5, 0x0e, 0x50, 0x7a, 0xb4, 0x82, 0x27, 0x52, 0x66, 0x60, 0x22, 0x05, 0x25, 0x4b, 0x2b, 0xa4, 0x24, 0x0a, 0x00, 0x00, 0x00, 0xff, 0xff]);


inflate(b, function(err, chunks, length) {
  console.log(chunks);
}

This ends up logging what looks like the correct opening series of bytes, but not the correct ending.


Sigh.... it seems that I will be assembling headers manually tomorrow.

Update: I figured it out! It was a simple matter of not including the correct number of octets / bytes for the headers. When I converted from spdy/2 to spdy/3, I accounted for the increase from 16 bit to 32 bit header length values everywhere except when totalling the length. All that I needed was an 8 (4 octets for the keys and 4 for the values) every time that I added a new key value pair to the header:

  // ...
  var len = 4,
      pairs = Object.keys(loweredHeaders).filter(function(key) {
        var lkey = key.toLowerCase();
        return lkey !== 'connection' && lkey !== 'keep-alive' &&
               lkey !== 'proxy-connection' && lkey !== 'transfer-encoding';
      }).map(function(key) {
        var klen = Buffer.byteLength(key),
            value = stringify(loweredHeaders[key]),
            vlen = Buffer.byteLength(value);

        len += 8 + klen + vlen;
        return [klen, key, vlen, value];
      }),
      result = new Buffer(len);

I cannot believe that I caused myself two nights of pain for an 4 when I meant 8. Binary protocols: catch the fever!

At any rate, I finally have a spdy/3 express site:

Tomorrow comes the great cleanup. I have a ton of debug statements in here.

Day #367

366 or How I Tricked Myself into Being Awesome

Like most developers, I am an introvert, so it is hard to say this:

I am awesome.

Fuuuuuu.... I can't even leave it at that. I look at so many amazing people in the Ruby, Javascript, and other communities that actually are amazing and I feel like I haven't done anything. But even so, looking back at the 366 days of the last year, what I did was, well... amazing.

I wrote three books on very different technologies that I knew nothing about.

I wrote The SPDY Book, which is still the only book on SPDY:

Three months later, I co-authored Recipes with Backbone(.js) with Nick Gauthier:

Three months later, I wrote the first book on Dart, Dart for Hipsters:

Each of these technologies has two things in common:

1. They are game changing (or at least possibly)
2. I knew nothing about them before I started writing them.

What business did I have writing books on topics about which I knew nothing? Well, let me put it this way: I did it so why shouldn't I (or anyone else)?

How did I do it?

Blogged every, single day. For one full year. 366 days. Every day. No matter what.

I honestly don't know why I started doing this. One night I had a brilliant idea and before I stopped and thought about how stupid it was, I publicly committed myself to doing it.

And it worked. Every night, I ask a question to which I don't know the answer and I try my damnedest to answer it.

Every time I do this, I learn. The daily deadline forces me to learn. Blogging about it challenges my assumptions and makes me learn even more.

And then, doing it again the next day reinforces the learning. As does writing the book. And the second edition.

I am proud that I didn't let this get in the way of what's important. I still took vacations with the family—drove to the beach and Disney World. Birthdays, anniversary, sickness—I was there for it all.

And in the end, what did I learn? Well aside from a ton about cool technologies, I learned that...

I tricked myself into being awesome

I heard a story on RadioLab about a lady named Zelda. She tricked herself into quitting smoking by swearing that she would donate $5,000 to the KKK if she ever smoked another cigarette. And she never did. Would she have really donated that money if she had given in? Maybe not, but it was enough for her to have convinced herself that it would happen.

And, in the end, I did the same. Would the world have ended if I missed a day? Of course not. Very few, if any people would have noticed. But I would have noticed because I committed to doing this. And, after 366 days, I have more than not smoking to show for it. I have three books, the last of which is being published by The Pragmatic Programmers.

So what's next?

Day 367.

What Should My Next Book Be?

I need to get started on my next book. There is so much more that I want to learn that I'm having a hard time choosing.

The Results

You can still suggest another in comments.

Bad SPDY/3 Headers

‹prev | My Chain | next›

Up tonight, I continue in my effort to get node-spdy working with SPDY version 3. I have Chrome speaking SPDY v3 by virtue of about:flags settings. I have begun SPDY v3 implementation in the node-spdy server by copying the v2 implementation to v3, updating the compression dictionary, and making a change or two to the header parsing.

As of last night, I am able to parse headers from the incoming session, but that is about it. No response is ever sent and I can see no evidence that the request listener ever sees the request.

The headers look like:

headers: 
   { ':host': 'localhost:3000',
     ':method': 'GET',
     ':path': '/',
     ':scheme': 'https',
     ':version': 'HTTP/1.1',
     accept: 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
     'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3',
     'accept-encoding': 'gzip,deflate,sdch',
     'accept-language': 'en-US,en;q=0.8',
     'cache-control': 'no-cache',
     pragma: 'no-cache',
     'user-agent': 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/536.8 (KHTML, like Gecko) Chrome/20.0.1105.0 Safari/536.8' } }

Now that I think about it, I have no idea why some of those headers begin with a colon (e.g. ':host'). That seems like it must be coming from Chrome. If it were a zlib inflation error, the values would have additional characters as well. Besides, a bit or two offset would cause the whole thing to crash.

The spdy/2 version of the headers definitely does not include the prepended colon:

headers:
   { accept: 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
     'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3',
     'accept-encoding': 'gzip,deflate,sdch',
     'accept-language': 'en-US,en;q=0.8',
     'cache-control': 'no-cache',
     host: 'localhost:3000',
     method: 'GET',
     pragma: 'no-cache',
     scheme: 'https',
     url: '/',
     'user-agent': 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/536.8 (KHTML, like Gecko) Chrome/20.0.1105.0 Safari/536.8',
     version: 'HTTP/1.1' }

So, I manually remove the colons from the header names in spdy/3:

protocol.parseHeaders = function parseHeaders(pairs) {
  // ...
  while(count > 0) {
    var k = readString(),
        v = readString();

    k = k.replace(/:/, '');
    headers[k] = v;

    count--;
  }

  return headers;
};

That gives me better headers:

headers:
   { host: 'localhost:3000',
     method: 'GET',
     path: '/',
     scheme: 'https',
     version: 'HTTP/1.1',
     accept: 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
     'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3',
     'accept-encoding': 'gzip,deflate,sdch',
     'accept-language': 'en-US,en;q=0.8',
     'cache-control': 'no-cache',
     pragma: 'no-cache',
     'user-agent': 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/536.8 (KHTML, like Gecko) Chrome/20.0.1105.0 Safari/536.8' } 

But still no response or even an attempt at a response.

Hrm... the spdy/3 SYN_STREAM does not have a url—could that be it?

protocol.parseHeaders = function parseHeaders(pairs) {
  // ...
  while(count > 0) {
    var k = readString(),
        v = readString();

    k = k.replace(/:/, '');
    headers[k] = v;

    if (k == 'path') {
      headers['url'] = v;
    }

    count--;
  }

  return headers;
};

As expected, that does produce a url request header:

headers: 
   { host: 'localhost:3000',
     method: 'GET',
     path: '/',
     url: '/',
     scheme: 'https',
     version: 'HTTP/1.1',
     // ...
   }

But, more importantly, I finally move past my block. The response is now being sent back to the browser:

writeHead
replyFrame
writeHead
write
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd"><html><head><title>Express</title><link rel="stylesheet" href="/stylesheets/style.css"/><script src="/main.js"></script></head><body><h1>Express</h1><p>Welcome to Express</p></body></html>
...

Unfortunately, this does not quite work as a server error still arises. But at least it is a different error this time. Tantalizingly close, I have to call it a night.

Update: The colon headers are, of course, part of the spec. Folding them back into a new url header is necessary, but removing the colons was not. It seems that the response also needs colon headers—hopefully that accounts for most of my remaining problems.

Day #366

Not-Actual SPDY v3 Conversation

‹prev | My Chain | next›

Yesterday, I was able to get my simple express.js prepped and ready for SPDY v3 with an assist from the latest and greatest node-spdy. I even have Chrome speaking SPDY v3 thanks to an about:flag setting. Only the SPDY conversation quickly dies.

This is almost certainly because I do not actually have v3 well defined in node-spdy (in fact, I only have an exact copy of v2). I begin my investigation with Wireshark.... only everything looks OK. I already know that the browser is SPDY v3 capable and Wireshark confirms that the server also thinks it is capable of talking SPDY v3:

Next stop: print-STDERR in the code!

But, before I can even write my first console.log(), I spy:

      // Fallback to HTTPS if needed
      if (socket.npnProtocol !== 'spdy/2' && !options.debug) {
        return connectionHandler.call(this, socket);
      }

So, even though both client and server believe that SPDY is about to ensue, the server begins talking plain-old HTTP over SSL. No wonder things are going badly.

I replace the SPDY guard with:

      // Fallback to HTTPS if needed
      if (!socket.npnProtocol.match(/spdy/) && !options.debug) {
        return connectionHandler.call(this, socket);
      }

After restarting and reloading the page, I am greeted with my old favorite, Error 337 (net::ERR_SPDY_PROTOCOL_ERROR): Unknown error.:

Good times.

But really, I did not expect that simply copying version 3 directly from the node-spdy version 2 implementation would work. Mercifully, the server error makes plan what the problem is:

➜  express-spdy-test  node app
Express server listening on port 3000 in development mode
node: ../src/node_zlib.cc:166: static void node::ZCtx::Process(uv_work_t*): Assertion `err == 0 && "Failed to set dictionary"' failed.
[1]    31988 abort (core dumped)  node app

The zlib compression dictionary did not work, nor should it—the dictionary was one of the many things that changed between SPDY v2 and v3.

Unfortunately, node-spdy hard-codes the dictionary in lib/utils.js rather than in a protocol version location. For now, I simply aim to get this working, not architected well, so I copy the dictionary from the spec into utils.js:

var dictionary = new Buffer([
 0x00, 0x00, 0x00, 0x07, 0x6f, 0x70, 0x74, 0x69,
 0x6f, 0x6e, 0x73, 0x00, 0x00, 0x00, 0x04, 0x68,
 0x65, 0x61, 0x64, 0x00, 0x00, 0x00, 0x04, 0x70,
...

Now, when I reload everything... I still get the same net::ERR_SPDY_PROTOCOL_ERROR error in the browser. On the plus side, the server is no longer crashing, so there's that!

The next bit of cleanup that I perform is to convert the header parsing from 16 bit to 32 bit. In SPDY version 2, the key value pairs (think HTTP headers) had been marked by 16 bit integers. Version 3 ups that to 32bit integers, mostly for consistency. At any rate, this involves replacing things like readUInt16BE with readUInt32BE and offsets of 2 with 4. Eventually, I am able to parse the incoming headers again:

headers: 
   { ':host': 'localhost:3000',
     ':method': 'GET',
     ':path': '/',
     ':scheme': 'https',
     ':version': 'HTTP/1.1',
     accept: 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
     'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3',
     'accept-encoding': 'gzip,deflate,sdch',
     'accept-language': 'en-US,en;q=0.8',
     'cache-control': 'no-cache',
     pragma: 'no-cache',
     'user-agent': 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/536.8 (KHTML, like Gecko) Chrome/20.0.1105.0 Safari/536.8' } }

I still am not sending a response back, however. I call it a night here and hope that I can get everything working tomorrow.



Day #365

Getting Started with SPDY v3

‹prev | My Chain | next›

Up tonight, I would like to experiment a bit with SPDY version 3. Much of the research that went into SPDY Book was based on the draft for version 3, but all of the code was written for version 2.

I seem to recall hearing mention that someone had started work on version 3 support in node-spdy, but I see nothing in the fork graph in GitHub. So I start on my own. First up, I link my locally cloned node-spdy so that npm will use it rather than trying to download it from the network:

➜  express-spdy-test  cd ~/repos/node-spdy
➜  node-spdy git:(master) npm link
...
mocha@0.10.2 ./node_modules/mocha
├── growl@1.4.1
├── debug@0.6.0
└── commander@0.5.2
../../local/node-v0.7.7/lib/node_modules/spdy -> /home/chris/repos/node-spdy

Then, in my simple express.js + SPDY site from the other night, I complete the link:

➜  node-spdy git:(master) cd ~/tmp/express-spdy-test
➜  express-spdy-test  npm link spdy
./node_modules/spdy -> /home/chris/local/node-v0.7.7/lib/node_modules/spdy -> /home/chris/repos/node-spdy
➜  express-spdy-test  npm ls
application-name@0.0.1 /home/chris/tmp/express-spdy-test
├─┬ connect@2.1.2 
│ └── ....
├─┬ express@2.5.9
│ └── ...
├─┬ jade@0.24.0
│ ├── ...
└─┬ spdy@1.2.0 -> /home/chris/repos/node-spdy
  ...

I really love that npm makes it easy to use packages as I develop like that.

It seems that Fedor Indutny has anticipated the next version of SPDY in that the current node-spdy has a v2 directory:

➜  node-spdy git:(master) ✗ ls -1 lib/spdy/protocol
generic.js
v2

And the code itself also looks to anticipate newer versions:

// lib/spdy.js
...
// Only SPDY v2 is supported now
spdy.protocol[2] = require('./spdy/protocol/v2');
...

The first thing to do is copy v2 to v3 in the file system and to add version 3 to lib/spdy.js:

// Supported SPDY versions
spdy.protocol[2] = require('./spdy/protocol/v2');
spdy.protocol[3] = require('./spdy/protocol/v3');

After verifying that this still works, I am ready to try out SPDY v3. I would tend to doubt that it would work without changes, but I need to start somewhere. In chrome://flags/, I enable SPDY v3:

I also need to relaunch:

I then reload the page to see... that I am still talking spdy/2 according to the SPDY tab in chrome://net-internals.

The good news is that Chrome does seem to be SPDY v3 ready. The bad news should be fixed by one more tweak to node-spdy—adding spdy/3 to the list of advertised protocols:

function Server(options, requestListener) {
    if (!options) options = {};
    if (!options.maxStreams) options.maxStreams = 100;
    options.NPNProtocols = ['spdy/3', 'spdy/2', 'http/1.1', 'http/1.0'];
    ...

Unfortunately, after restarting the server, I get variations of server unavailable or empty response:

Ah well. It was a bit much to expect this to work immediately. I call it a night here and will pick back up tomorrow inspecting packets in Wireshark.

Day #364

SPDY Ping

‹prev | My Chain | next›

I would very much like to move on to exploring flow control in SPDY, but first feel like it is a good idea to address a small bug in express-spdy. Express-spdy will be going away very soon since recent versions of node-spdy proper support express.js integration out of the box. But that will not be ready until the next node.js stable release. Since that may not be in time for the impending 1.1 edition of SPDY Book, I should get my express-spdy house in order.

The particular bug is that, after the initial SPDY connection goes through, the follow error occurs:

SPDY_SESSION_PING
--> type = "sent"
--> unique_id = 1
SPDY_SESSION_CLOSE
--> description = "Failed ping."
--> status = -352
SPDY_SESSION_POOL_REMOVE_SESSION
--> source_dependency = 683722 (SPDY_SESSION)

The browser sends a PING to the server, but the server fails to respond. In fact, the server is incapable of responding because the older version of node-spdy being used is PING-ignorant. Naturally, this all works in the recent node-spdy, but that does not help.

In the core SPDY server, the SPDY connection is piped through to an instance of a SPDY parser. I add a check for PINGs to the end of that parser:

// ...
    c.pipe(parser);

    parser.on('cframe', function(cframe) {
      if (cframe.headers.type == enums.SYN_STREAM) {
        // Do SYN_STREAM stuff...
      } else if (cframe.headers.type == enums.RST_STREAM) {
        // Do RST_STREAM stuff ...
      } else if (cframe.headers.type == enums.PING) {
        console.log("PINGed!");
      }
    });
// ...

After reloading the server and refreshing the browser, I see that the server does recognize this PING:

➜  express-spdy-old  node app
Express server listening on port 3000 in development mode
PINGed!

The old node-spdy defined methods like createRstFrame and createSettingsFrame but, since it was PING ignorant, there is not a corresponding createPingFrame. I will eventually create one, but for now, I use the lower level createControlFrame() method to respond to the first PING:

      // ...
      } else if (cframe.headers.type == enums.PING) {
        console.log("PINGed! " + cframe.data.streamID);
        var streamID = 1;

        c.write(createControlFrame(c.zlib, {
          type: enums.PING
        }, new Buffer([
          (streamID >> 24) & 255, (streamID >> 16) & 255,
          (streamID >> 8) & 255, streamID & 255
        ])));
      }
      // ...

That does the trick as the browser now gets back its desired PING:

SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 3
SPDY_SESSION_PING
--> type = "sent"
--> unique_id = 1
SPDY_SESSION_PING
--> type = "received"
--> unique_id = 1

And, more importantly, the connection remains open:

The only problem is that I have hard-coded the SPDY session ID to one. The parser seems unable to extract the ID from the PING request:

➜  express-spdy-old  node app
Express server listening on port 3000 in development mode
PINGed! undefined

This may be due to PING using a 32 bit ID. I will pick back up here tomorrow and hopefully close the book on the old express-spdy.

Update: The cause had nothing to do with the size of the ID and everything to do with not parsing PING packets—the old node-spdy simplely did not do it. So I add that capability:

Parser.prototype.parse = function() {
  // ...
  if (headers.c) {
    if (headers.type === enums.SYN_STREAM) { /* ... */ }
    if (headers.type === enums.SYN_REPLY) { /* ... */ }
    if (headers.type === enums.RST_STREAM) { /* ... */ }
    if (headers.type === enums.PING) {
      var parsed = {
        streamID: data.readUInt32BE(0) & 0xffffffff
      };
      data = parsed;
    }
    // ...
  }

  this.emit(headers.c ? 'cframe' : 'dframe', {
    headers: headers,
    data: data
  });
  // ...
};

With that, not only to I see the initial stream ID of "1", but I also see the correct stream ID for subsequent PINGs:

➜  express-spdy-old  node app
Express server listening on port 3000 in development mode
PINGed! 1
PINGed! 3
...

Day #263

mod_spdy: revisited

‹prev | My Chain | next›

I remain undecided about how I should approach node-spdy in the updated edition of SPDY Book, so tonight I take a break. Instead I am going to kick the tires on mod_spdy. When I first got started on this current kick of writing, I looked at mod_spdy and came to the conclusion that it was not worth expending time. A year later, that is no longer the case.

First up, I grab the 64 Ubuntu package (I do not miss compiling that gclient source code):

$ wget https://dl-ssl.google.com/dl/linux/direct/mod-spdy-beta_current_amd64.deb

Then I install:

sudo dpkg -i mod-spdy-beta_current_amd64.deb 
...
Setting up mod-spdy-beta (0.9.1.5-r301) ...
Enabling module spdy.
To activate the new configuration, you need to run:
  service apache2 restart

I follow those instructions (restarting apache), then access my local SSL server at https://jaynestown.local, and...

It works. I access my old SSL site and, checking out the SPDY tab in chrome://net-internals, I actually have a legitimate SPDY session:

Wow. That was incredibly easy. When I tried this a year ago, I despaired that writing The SPDY Book might well prove impossible on the first day I researched it, thanks to mod_spdy. Now, I can install a Deb package and I am running immediately. Amazing.

Some important notes: I benefit from running Ubuntu 12.04, which comes with a version of openssl that is capable of Next Protocol Negotiation (NPN). Without that, the browser would have no way of knowing that Apache was SPDY-enabled. I spent some time last year configuring my SSL server, some of the highlights of which are:

<VirtualHost _default_:443>
        DocumentRoot /var/www
        # ...
        SSLEngine on
        # ...
        SSLCertificateFile    /etc/ssl/certs/jaynestown.crt
        SSLCertificateKeyFile /etc/ssl/private/jaynestown.key
        # ...
</VirtualHost>

I even spent a good deal of time setting myself as a CA (locally).

The bottom line is that SSL configuration is pretty easy, but not needing to install an edge version of openssl makes any pain of using a Beta Ubuntu more than worth it.

As for the mod_spdy module itself, aside from working, there is not much else to explore. Work it does, but there are relatively few configuration options. I am already eagerly waiting for SPDY server push configuration settings in a forthcoming release.

Day #362

Edge SPDY, Node.js, and Express.js

‹prev | My Chain | next›

I am slowly coming to the conclusion that this may not be the best time to issue a 1.1 edition of SPDY Book. Much of the new hotness that is node-spdy is in limbo until the unstable 0.7 node.js becomes stable 0.8. I almost have a handle on that except for express.js, the pleasant HTTP resource-oriented application server. The current 2.0 series will work with edge node-spdy, but not 0.7/0.8 node.js. For 0.8 node.js, the 3.0 alpha of express.js is imminent—only it does not play well with node-spdy.

All of these moving parts have me thinking that a more modest SPDY Book update might be the better part of valor. But I am not quite ready to give up. First, I would like to have a go at getting edge node-spdy and edge express.js working together.

The latest node-spdy does a rather elegant thing when creating SPDY-sized servers—it accepts an optional class argument that can be used to decorate server-like objects. This is specifically used to create express.js instances as I found last night:

var app = spdy.createServer(express.HTTPSServer, options);

The problem presented by edge express.js is that there is no express.HTTPSServer class anymore. In particular, the new express.application is more of a mixin than a proper class.

The answer (hopefully) is that node-spdy also works with HTTP server objects, which is what the express() function ought to return in 3.0. I have my forks of express.js and connect.js (for middleware) checked out locally. I have to modify the package.json for each to be compatible with 0.7:

{
  "name": "express",
  "description": "Sinatra inspired web development framework",
  // ...
  "engines": { "node":">= 0.5.0 < 0.9.0" }
}

With that, I can install globally and use the resultant generator to get started on an express3 application:

➜  tmp  npm install -g ~/repos/express/ ~/repos/connect
➜  tmp  express express3-spdy-test
➜  tmp  cd express3-spdy-test
➜  express3-spdy-test  npm install ~/repos/express ~/repos/connect ~/repos/node-spdy
➜  express3-spdy-test  npm install jade

I also copy the SSL keys from my 2.0 test application:

➜  express3-spdy-test  mkdir keys
➜  express3-spdy-test  cp ../express-spdy-test/keys/* keys 
➜  express3-spdy-test  ls keys 
spdy-cert.pem  spdy-csr.pem  spdy-key.pem

I can start up the generated express 3.0 app:

➜  express3-spdy-test  node app
Express server listening on port 3000

Pointing the browser at that site, I get the expected default homepage:

Next, I need an SSL version of the site. For that I change the http.createServer() to the https equivalent in the application app.js file:

// ...
var options = {
  key: fs.readFileSync(__dirname + '/keys/spdy-key.pem'),
  cert: fs.readFileSync(__dirname + '/keys/spdy-cert.pem'),
  ca: fs.readFileSync(__dirname + '/keys/spdy-csr.pem')
};

https.createServer(options, app).listen(3000);

After restarting, I can now access the default express.js site over SSL:

Now for the moment of truth: switching to node-spdy. I add spdy to the list of required packages and replace the https.createServer with the node-spdy equivalent:

var express = require('express')
  , routes = require('./routes')
  , http = require('http')
  , https = require('https')
  , spdy = require('spdy')
  , fs = require('fs');

var app = express();

app.configure(function(){ /* ... */ });

app.get('/', routes.index);

var options = {
  key: fs.readFileSync(__dirname + '/keys/spdy-key.pem'),
  cert: fs.readFileSync(__dirname + '/keys/spdy-cert.pem'),
  ca: fs.readFileSync(__dirname + '/keys/spdy-csr.pem')
};

//https.createServer(options, app).listen(3000);
spdy.createServer(https.Server, options, app).listen(3000);

After starting the server, I can again access the homepage over SSL, but this time, when I check the SPDY tab in Chrome's chrome://net-internals, I have SPDY!

SPDY_SESSION_SYN_STREAM
--> flags = 1
--> accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
    accept-charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
    accept-encoding: gzip,deflate,sdch
    accept-language: en-US,en;q=0.8
    cache-control: no-cache
    cookie: [value was stripped]
    host: localhost:3000
    method: GET
    pragma: no-cache
    scheme: https
    url: /
    user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/536.8 (KHTML, like Gecko) Chrome/20.0.1105.0 Safari/536.8
    version: HTTP/1.1
--> id = 1
SPDY_SESSION_RECV_SETTING
--> flags = 1
--> id = 4
--> value = 100
SPDY_SESSION_SYN_REPLY
--> flags = 0
--> content-length: 277
    content-type: text/html; charset=utf-8
    status: 200 OK
    version: HTTP/1.1
    x-powered-by: Express
--> id = 1
...

Aw, man! That is nice. I was really worried that the new express.js would be incompatible, but clearly my worries were completely unfounded. Not only does it work, but it is really easy to configure and get running. Once again, kudos to Fedor Indunty for the very slick implementation.

Despite the ease with which I got all of this up and running, I am still in a bit of a bind with regards to including edge stuff like this in the updated book or sticking with express-spdy, which is clearly no longer needed. The former is a moving target and the latter is likely to be obsolete days after I put out the next edition of The SPDY Book. I think this suggests that minimal changes for now might be the best course of action, but I will sleep on it before making a decision.

If nothing else, the future of SPDY on node.js looks quite nice.


Day #361

SPDY Server Push in Edge Node-SPDY

‹prev | My Chain | next›

As of last night, I know how to SPDY-ize express.js applications with only node-spdy—no express-spdy required. This requires a bit of futzing (switching down to express.js 2.x because node-spdy won't work with 3.x and modifying express to run on unstable node.js 0.7). I will worry about compatibility another day. Today, I would like to get SPDY server push working with this configuration.

The node-spdy documentation suggests that a push stream can be initiated with (this was corrected):

spdy.createServer(options, function(req, res) {
  var headers = { 'content-type': 'application/javascript' };
  res.send('/main.js', headers, function(err, stream) {
    if (err) return;

    stream.end('alert("hello from push stream!");');
  });

  res.end('<script src="/main.js"></script>');
}).listen(443);

That will not work for my case because this is a dumb server that responds to all requests with nothing more than a document containing: <script src="/main.js"></script> (the res.end() line at the end). This will not give express.js a chance to kick in and do its thing. Also, I think that the res.send() line is meant to be res.push().

This is easy enough to try out, I save the dumb server, fire it up, and load the page in Chrome. This promptly results in a crash:

➜  express-spdy-test  node app

node.js:247
        throw e; // process.nextTick error, or 'error' event on first tick
              ^
TypeError: Cannot read property 'method' of undefined
    at ServerResponse.send (/home/chris/tmp/express-spdy-test/node_modules/express/lib/response.js:108:30)
    at Server.<anonymous> (/home/chris/tmp/express-spdy-test/app.js:21:7)
    at Server.emit (events.js:70:17)
    at Connection.<anonymous> (/home/chris/tmp/express-spdy-test/node_modules/spdy/lib/spdy/server.js:61:14)
    at Connection.emit (events.js:70:17)
    at HTTPParser.onIncoming (http.js:1665:12)
    at HTTPParser.onHeadersComplete (http.js:115:25)
    at Stream.ondata (http.js:1562:22)
    at Array.0 (/home/chris/tmp/express-spdy-test/node_modules/spdy/lib/spdy/server.js:544:27)
    at EventEmitter._tickCallback (node.js:238:41)

Yup. Line 21 is the res.send(). So I convert that to res.push():

var app = spdy.createServer(options, function(req, res) {
  var headers = { 'content-type': 'application/javascript' };
  res.push('/main.js', headers, function(err, stream) {
    if (err) return;

    stream.end('alert("hello from push stream!");');
  });

  res.end('<script src="/main.js"></script>');
});

Now, I get my expected alert():

Man, I love SPDY server push. Chrome makes a request, to which the dumb server always replies "<script src="/main.js"></script>". Without SPDY server push, this would result in the browser making a second request of the server for the /main.js resource. But, using SPDY server push, we have already pushed the contents of /main.js into browser cache—in this case the alert() dialog. By the time the browser realizes it needs to request /main.js, it is already in browser cache so no request is actually made and the content is served directly from cache.

Checking things over in the SPDY tab of chrome://net-internals, I see that there is, indeed, a SPDY push stream taking place:

SPDY_SESSION_SYN_STREAM
--> flags = 1
--> host: localhost:3000
    method: GET
    url: /
    version: HTTP/1.1
    ....
--> id = 1
SPDY_SESSION_PUSHED_SYN_STREAM
--> associated_stream = 1
--> flags = 2
--> content-type: application/javascript
    status: 200
    url: https://localhost:3000/main.js
    version: HTTP/1.1
--> id = 2
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 33
--> stream_id = 2
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 2
SPDY_SESSION_SYN_REPLY
--> flags = 0
--> status: 200 OK
    version: HTTP/1.1
--> id = 1
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 32
--> stream_id = 1
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 1

The only problem with the above SPDY server push is that the entire contents of the push are sent before the page response. In SPDY, data and headers are separate—even in push. It would likely be more proper to send just the headers in the form of SPDY_SESSION_PUSHED_SYN_STREAM, then complete the SYN_REPLY and send all data associated with the initial request along on stream #1 before sending the pushed data. That is a minor quibble (and one that can be addressed another day). For now, it is pretty cool that SPDY push works so well.

With that, I can return to my SPDY-ized express site. To perform a SPDY push in express, I need to modify my index route:

exports.index = function(req, res){
  res.render('index', { title: 'Express' });
};

Just as in the dumb server, I add a res.push() statement:

exports.index = function(req, res){
  var headers = { 'content-type': 'application/javascript' };
  res.push('/main.js', headers, function(err, stream) {
    if (err) return;

    stream.end('alert("hello from push stream!");');
  });

  res.render('index', { title: 'Express' });
};

I also need to tell my Jade layout to request /main.js:

!!!
html
  head
    title= title
    link(rel='stylesheet', href='/stylesheets/style.css')
    script(src='/main.js')
  body!= body

With that, I get the alert() pushed into cache. Once I click OK, the normal express page loads:

Kudos to Fedor Indutny on that API—I think that is an improvement on the original SPDY push that I had hacked into node-spdy. It is easy and makes sense. This is why I write the books, not the original code.


Day #360

Edge Node-SPDY and Express.js

‹prev | My Chain | next›

I am back on edge node-spdy and the view is wonderful. To be sure there are drawbacks suck as only running on edge node.js—but that is a also a benefit since edge node.js bundles a SPDY-friendly version of openssl. One of the other features of edge node-spdy is that it supports express.js out of the box. Tonight I am going to try to see how that works.

My first instinct is to install edge express.js (along with edge connect.js) in order to get this working:

➜  express-spdy-test  npm install ~/repos/express ~/repos/connect ~/repos/node-spdy
...
spdy@1.2.0 ./node_modules/spdy

express@3.0.0alpha1-pre ./node_modules/express
├── debug@0.6.0
├── commander@0.5.2
├── mime@1.2.5
└── mkdirp@0.3.0

connect@2.1.2 ./node_modules/connect
├── debug@0.6.0
├── qs@0.4.2
├── mime@1.2.4
├── formidable@1.0.9
└── crc@0.1.0

I am not 100% clear if this will work because express.js has changed in preparation for the 0.8 series of node.js. The new 3.0 series of express.js features, among other things, a server object created with the express() method rather than the current createServer(). I have no idea how deep such changes go. Breaking things is one way to find out...

I start with a modified version of a generated express.js app.js:

var express = require('express')
  , spdy = require('spdy')
  , fs = require('fs')
  , routes = require('./routes');

//var app = module.exports = express.createServer();
var app = spdy.createServer(express.HTTPSServer, {
  key: fs.readFileSync(__dirname + '/keys/spdy-key.pem'),
  cert: fs.readFileSync(__dirname + '/keys/spdy-cert.pem'),
  ca: fs.readFileSync(__dirname + '/keys/spdy-csr.pem')
});

I require express, spdy and a couple other necessary modules. Then I create an app server instance via node-spdys' createServer() constructor. The first argument passed into createServer() is the base class used to create the application server instance—node-spdy should just decorate this instance with a few tweaks of its own.

When I start the server up, however, I get:

➜  express-spdy-test  node app                             

node.js:247
        throw e; // process.nextTick error, or 'error' event on first tick
              ^
Error: addListener only takes instances of Function
    at Server.<anonymous> (events.js:101:11)
    at Server.Server (https.js:38:10)
    at new Server (/home/chris/tmp/express-spdy-test/node_modules/spdy/lib/spdy/server.js:24:17)
    at Object.create [as createServer] (/home/chris/tmp/express-spdy-test/node_modules/spdy/lib/spdy/server.js:98:10)
    at Object.<anonymous> (/home/chris/tmp/express-spdy-test/app.js:12:16)
    ....

Hrm... that error is coming from node-spdy itself. Ah, after a bit of investigation, I realize that express.HTTPSServer is undefined in express 3.0.

Instead, I try passing in the other option suggested by the node-spdy documentation: https.Server:

var app = spdy.createServer(https.Server, {
  // ...
});

This changes the message, but still does not give me a SPDY-enabled express.js:

➜  express-spdy-test  node app

node.js:247
        throw e; // process.nextTick error, or 'error' event on first tick
              ^
TypeError: Object #<Server> has no method 'configure'
    at Object.<anonymous> (/home/chris/tmp/express-spdy-test/app.js:22:5)
    ...

I would not expect https.Server to respond to configure(). That is an express.js method whereas https.Server comes from node.js core.

So I give up, for now, on trying to get this working with the 3.0 series of express.js. Instead, I switch my local fork of express.js back to the 2.x series. Specifically, my fork includes the provision that this will work with the unstable version of node.js in package.json:

{ 
  "name": "express",
  "description": "Sinatra inspired web development framework",
  "version": "2.5.9",
  "author": "TJ Holowaychuk ",
  // ....
  "engines": { "node": ">= 0.4.1 < 0.9.0" }
}

I re-install in my test application directory:

➜  express-spdy-test  npm install ~/repos/express ~/repos/connect ~/repos/node-spdy

And I change the app.js server to create express.HTTPSServer objects:

//var app = module.exports = express.createServer();
var app = spdy.createServer(express.HTTPSServer, {
  // ...
});

With that, I get the server to start up:

➜  express-spdy-test  node app
Express server listening on port 3000 in development mode

And a quick inspection of chrome://net-internals reveals that I do have a legitimate SPDY server.

Day #359

Getting Started with Node-Spdy Edge

‹prev | My Chain | next›

Last night I was able to confirm that express-spdy does not work with node.js installs that are built against older versions of openssl (i.e. those that lack NPN / Next Protocol Negotiation). I set off down the rabbit hole of trying to get exress-spdy to not install if it detected an older openssl, but was not able to get that working.

Tonight, I am abandoning that effort and instead following the advice of Fedor Indutny, node.js coder extraordinaire and author of the very excellent node-spdy package. He suggested that I drop my efforts in the node.js stable branch in favor of the unstable 0.7.x series. The 0.7.x bundles an NPN capable openssl. It has the additional benefit of node-spdy 1.0. I had planned on playing with that eventually. Now seems a good time.

So, in a temporary directory, I install node-spdy:

➜  tmp  cd    
➜  ~  cd ~/tmp
➜  tmp  mkdir node-spdy-test
➜  tmp  cd !$
➜  tmp  cd node-spdy-test
➜  node-spdy-test  which node
/home/chris/local/node-v0.7.7/bin/node
➜  node-spdy-test  npm install spdy     
npm http GET https://registry.npmjs.org/spdy
npm http 304 https://registry.npmjs.org/spdy
npm http GET https://registry.npmjs.org/spdy/-/spdy-1.2.0.tgz
npm http 200 https://registry.npmjs.org/spdy/-/spdy-1.2.0.tgz
spdy@1.2.0 ./node_modules/spdy

The, I define a simple server in app.js:

var spdy = require('spdy'),
    fs = require('fs');

var options = {
  key: fs.readFileSync(__dirname + '/keys/jaynestown.key'),
  cert: fs.readFileSync(__dirname + '/keys/jaynestown.crt'),
  ca: fs.readFileSync(__dirname + '/keys/jaynestown.csr')
};

var server = spdy.createServer(options, function(req, res) {
  res.writeHead(200);
  res.end('hello world!');
});

server.listen(3000);

And, lastly, I run that server:

➜  node-spdy-test  node app.js

Checking things out in the SPDY tab of Chrome's about:net-internals, I see a nice, legit SPDY session:

t=1334632829005 [st=   0]  SPDY_SESSION_PING
                           --> type = "sent"
                           --> unique_id = 3
t=1334632829005 [st=   0]  SPDY_SESSION_SYN_STREAM
                           --> flags = 1
                           --> accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
                               accept-charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
                               accept-encoding: gzip,deflate,sdch
                               accept-language: en-US,en;q=0.8
                               cache-control: no-cache
                               host: jaynestown.local:3000
                               method: GET
                               pragma: no-cache
                               scheme: https
                               url: /
                               user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/536.6 (KHTML, like Gecko) Chrome/20.0.1096.1 Safari/536.6
                               version: HTTP/1.1
                           --> id = 5
t=1334632829011 [st=   6]  SPDY_SESSION_PING
                           --> type = "received"
                           --> unique_id = 3
t=1334632829048 [st=  43]  SPDY_SESSION_SYN_REPLY
                           --> flags = 0
                           --> status: 200 OK
                               version: HTTP/1.1
                           --> id = 5
...

Dang, that was nice and easy.

Day #358

Express-Spdy on Old OpenSSL

‹prev | My Chain | next›

Last night, I got express-spdy working out of the box on Ubuntu 12.04 in 5 easy steps. It worked so well that I wonder if something in node.js is making this so easy or if it really was Ubuntu 12.04.

So, on an old Ubuntu 10.04 box, I:

1. install node.js v0.6.15
2. Install the generator: $ npm install -g express-spdy
3. Generate a test server: $ express-spdy expess-spdy-test
4. Install the modules necessary for the test server:$ cd expess-spdy-test && npm install
5. Fire up the server: $ node app

When I access the site, nothing happens—the site never returns.

Watching the conversation in Wireshark, I note that there is, indeed, no NPN (next protocol negotiation) taking place in the server hello portion of the SSL handshake:

Contrast this, for instance, with the SSL handshake from the 12.04 server:

I am hard pressed to decide if this is proper behavior for express-spdy. It makes no sense to use express-spdy without a version of openssl capable of NPN (per the openssl changelog, that means openssl version 1.0.1 or higher).

The only thing that actually compiles C code in the entire express-spdy dependency tree is the zlib compesssion code, which is not a place to be checking for the proper SSL versions. What if I use the node extension toolset, but only to check prerequisites? In that case, the package.json might add a script section like:

{
  "author": "Chris Strom  (http://eeecomputes.com)",
  "name": "express-spdy",
  "description": "SPDY-ize express.js sites.",
  "version": "0.2.0",
  "homepage": "https://github.com/eee-c/express-spdy",
  "scripts": {
    "preinstall" : "node-waf configure"
  },
  // ...
}

I then need a corresponding wscript file:

def set_options(opt):
  opt.tool_options('compiler_cxx')

def configure(conf):
  conf.check_cfg(package='openssl', atleast_version='1.0.1', mandatory=True)

When I try to install on my old machine, I get an error, but compilation proceeds anyway:

└── express@2.5.9 (qs@0.4.2, mime@1.2.4, connect@1.8.6)
cstrom@londo:~/repos/dummy$ npm install ../express-spdy/

> express-spdy@0.1.3 preinstall /home/cstrom/repos/dummy/node_modules/express-spdy
> node-waf configure

Setting srcdir to                        : /home/cstrom/repos/dummy/node_modules/express-spdy
Setting blddir to                        : /home/cstrom/repos/dummy/node_modules/express-spdy/build
Checking for openssl >= 1.0.1            : no
'configure' finished successfully (0.009s)

I do not know enough about WAF or node-waf to understand why this would not fail outright. It seems like it ought to halt. Somewhat frustrated, I call it a night here. I will bone up on my WAF tomorrow and hopefully come up with a way of getting this to fail.

Day #357