One Step Back, Two Steps Forward on SPDY Server Push

‹prev | My Chain | next›

Up tonight, I hope to actually initiate a server push in SPDY. Even if the push is entirely contrived, I would like to see it in action.

Building on last night's progress in the node-spdy codebase, I need to actually send the push stream that I (hopefully) have in place. So, in the Response class, I add a call to a new pushStuff() method when I write a normal response header (e.g. a response to a request for the app's homepage):

/**
 * Flush buffered head
 */
Response.prototype._flushHead = function() {
  if (this._written) {
    throw Error('Headers was already written');
  }
  this._written = true;

  var headers = this._headers;

  headers.status = this.statusCode + ' ' + this._reasonPhrase;
  headers.version = 'HTTP/1.1';

  var cframe = createControlFrame(this.c.zlib, {
    type: enums.SYN_REPLY,
    streamID: this.streamID
  }, headers);

  this.pushStuff();

  return this.c.write(cframe);
};

I then define pushStuff() to invoke the push stream class that I wrote yesterday:

Response.prototype.pushStuff = function() {
  var push_stream = createPushStream(this.cframe, this.c);
  push_stream.end(
    "h1 { color: orange }"
  );
};

The PushStream class from last night is equally contrived—currently it always sends headers for the node-spdy sample app's CSS. Thus, if I have this implemented correctly, SPDY will server push a substitute CSS that colors the title orange and applies not other styles. Chrome will then see that the page is cached and not request the real CSS file.

What I find, however is:

➜  node-spdy  node test/spdy-server.js
TLS NPN Server is running on port : 8081

/home/cstrom/repos/node-spdy/lib/spdy/response.js:168
  var push_stream = createPushStream(this.cframe, this.c);
                    ^
TypeError: undefined is not a function
    at CALL_NON_FUNCTION (native)
    at [object Object].pushStuff (/home/cstrom/repos/node-spdy/lib/spdy/response.js:168:21)
    at [object Object]._flushHead (/home/cstrom/repos/node-spdy/lib/spdy/response.js:66:8)
    at [object Object]._write (/home/cstrom/repos/node-spdy/lib/spdy/response.js:86:10)
    at [object Object].write (/home/cstrom/repos/node-spdy/lib/spdy/response.js:106:15)
    at [object Object].ondata (stream.js:36:26)
    at [object Object].emit (events.js:64:17)
    at [object Object]._emitData (fs.js:1008:10)
    at afterRead (fs.js:990:10)
    at wrapper (fs.js:245:17)

Hunh? How can createPushStream not be defined? I have very carefully defined, exported, and required it in all the same places that the already working createResponse is working.

It turns out the problem is in the main spdy.js file:

...
/**
 * response
 */
spdy.Response = require('./spdy/response').Response;
spdy.createResponse = require('./spdy/response').createResponse;

/**
 * push stream
 */
spdy.PushStream = require('./spdy/push_stream').PushStream;
spdy.createPushStream = require('./spdy/push_stream').createPushStream;
...

It takes me waaaaaaaay too long to determine that error is being caused because createPushStream is not defined in Response. Actually, the stacktrace makes it fairly clear that it is not defined, but it is the reason it is not defined that causes me so much trouble.

It turns out to be simple enough: the PushStream and createPushStream functions need to be defined in node-spdy's global object space before the Response class is defined. Otherwise, the Response class assigns undefined values to locally scoped variables of the same name:

/**
 * Response class
 */

var Buffer = require('buffer').Buffer,
    util = require('util'),
    stream = require('stream'),
    enums = require('../spdy').enums,
    createControlFrame = require('../spdy').createControlFrame,
    createDataFrame = require('../spdy').createDataFrame,
    PushStream = require('../spdy').PushStream,
    createPushStream = require('../spdy').createPushStream,
    createParser = require('../spdy').createParser;
...

In retrospect, the cause and solution are equally obvious, switch the order of importing PushStream and Response into the global node-spdy object space (defining PushStream first):

/**
 * push stream
 */
spdy.PushStream = require('./spdy/push_stream').PushStream;
spdy.createPushStream = require('./spdy/push_stream').createPushStream;

/**
 * response
 */
spdy.Response = require('./spdy/response').Response;
spdy.createResponse = require('./spdy/response').createResponse;

Obvious, but wow, did it take me a long time to get there.

With that sorted out, I start up the server and access the test app with Chrome. And this is what I see:



Ew.

If nothing else, that is a new error on me ("Error 337 (net::ERR_SPDY_PROTOCOL_ERROR): Unknown error."). Diggin a little deeper, I check out the SPDY session in Chrome's about:net-internals to find:

localhost:8081 (DIRECT)

Start Time: Fri May 27 2011 23:36:27 GMT-0400 (EDT)

t=1306553787440 [st= 0] +SPDY_SESSION  [dt=?]
                         --> host = "localhost:8081"
                         --> proxy = "DIRECT"
t=1306553787440 [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
                                cookie: [value was stripped]
                                host: localhost:8081
                                method: GET
                                pragma: no-cache
                                scheme: https
                                url: /
                                user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.36 (KHTML, like Gecko) Chrome/13.0.767.1 Safari/534.36
                                version: HTTP/1.1
                            --> id = 1
t=1306553787455 [st=15]     SPDY_SESSION_RECV_SETTINGS  
                            --> settings = ["[0:100]"]
t=1306553787485 [st=45]     SPDY_SESSION_RECV_DATA  
                            --> flags = 0
                            --> size = 20
                            --> stream_id = 2
t=1306553787485 [st=45]     SPDY_SESSION_RECV_DATA  
                            --> flags = 0
                            --> size = 0
                            --> stream_id = 2
t=1306553787485 [st=45]     SPDY_SESSION_SEND_RST_STREAM  
                            --> status = 1
                            --> stream_id = 1
t=1306553787487 [st=47]     SPDY_SESSION_RECV_DATA  
                            --> flags = 0
                            --> size = 698
                            --> stream_id = 1
t=1306553787487 [st=47]     SPDY_SESSION_RECV_DATA  
                            --> flags = 0
                            --> size = 0
                            --> stream_id = 1

Mercifully, I finally realize some progress. The stream_id is 2 for two of those frames, which means that the push stream is being emitted (streams initiated by the server are required by the SPDY spec to have even ID numbers). Obviously something is not quite kosher, but I can live with calling it a night here. Tomorrow, I should be able to address this issue and, hopefully, get legit SPDY server push in place.


Day #32