Monday, June 6, 2011

Vows for SPDY Push

‹prev | My Chain | next›

I am about ready to pull back from my SPDY server push spike and implement for real in node-spdy. But it has been a while since I have done serious vows.js testing so this may take a bit.

Actually, it may not. When I run the existing test suite for node-spdy, I get:
➜  node-spdy git:(push-stream) vows test/spdy-basic-test.js --spec

♢ SPDY/basic test

spdy.createServer
✓ should return spdy.Server instance
Listening on this server instance
✓ should be successfull
Calling spdy.createZLib
✓ should return instance of spdy.ZLib
Creating new connection to this server
✓ should receive connect event
Creating parser and waiting for SYN_REPLY
✓ should end up w/ that frame
Sending control SYN_STREAM frame should be successfull and sending request body
✓ should emit data and end events on request
Creating parser and waiting for Data packet
✗ should end up w/ that frame
» expected 1,
got 0 (==) // spdy-basic-test.js:140

✓ should end up w/ that frame
When calling server.close
✓ all connections will be dropped

✗ Broken » 7 honored ∙ 1 broken (0.036s)
The test structure for this basic test is... interesting. Most of the topics and vows are setting test-local variables to be re-used later on in the test suite. For instance, the connection variable is declared outside of the test suite:
var spdy = require('../lib/spdy');

var server,
connection,
//...
And is assigned inside the "Creating new connection" topic:
vows.describe('SPDY/basic test').addBatch({
'spdy.createServer': {
//...
}
}).addBatch({
'Listening on this server instance': {
//...
}
}).addBatch({
'Creating new connection to this server': {
topic: function() {
connection = require('tls').connect(PORT, 'localhost', options, this.callback);
},
'should receive connect event': function() {
}
},
'Calling spdy.createZLib': {
topic: function() {
return spdy.createZLib();
},
'should return instance of spdy.ZLib': function(_zlib) {
zlib = _zlib;
assert.instanceOf(zlib, spdy.ZLib);
}
}
}).addBatch({
//...
Later on there is a separate topic that pipes that connection directly into a node-spdy Parser object:
//...
'Creating parser': {
topic: function() {
var parser = spdy.createParser(zlib);

connection.pipe(parser);

return parser;
},
//...
The failure that I am seeing is occurring in one of the two sub-contexts for this parser:
//...
'Creating parser': {
//...
'and waiting for SYN_REPLY': {
//...
},
'and waiting for Data packet': {
//...
}
}
//...
It is in the second sub-context, the waiting for the Data packet context, in which I am experiencing problems. Specifically, I am getting a 1 for 0 error:
  Creating parser and waiting for Data packet
✗ should end up w/ that frame
» expected 1,
got 0 (==) // spdy-basic-test.js:137
The value of 1 is setting the expectation that there is a data FIN flag set on the first data frame received. But clearly that is not the case now.

The key word in that last sentence is "now". The data frame being received is the server push frame. I am sending out a separate, empty data FIN frame for the server push, so the first data push frame is devoid of FIN flags, hence the error.

Hrm... I am not quite ready to abandon my spike, but hate to proceed with that test failing. Actually, this is probably a good time to break out a separate vows suite for server push itself. From a high level, I expect the test to be exactly the same as this one, except that there is no FIN on the data packet:
//...
'should end up with the push frame': function(dframe) {
assert.ok(!dframe.headers.c);
assert.equal(dframe.headers.flags & spdy.enums.DATA_FLAG_FIN, 0);
}
//...
I save that into a separate test/spdy-push-test.js and run it to find:
...
Creating parser and waiting for Data packet
✓ should end up with the push frame
✗ should end up with the push frame
» expected 0,
got 1 (==) // spdy-push-test.js:143
...
Hunh? How could it fail in both suites? Ah, I see. It is getting called twice. The first time through it passes, but the second time through, it fails. I only want to call it once, so I create a closure in the topic to only call it a single time:
      topic: function(parser) {
var callback = this.callback;
var called = false;
parser.on('dframe', function(dframe) {
if (!called) {
callback(null, dframe);
}
called = true;

});
},
With that, I have my passing suite:
➜  node-spdy git:(push-stream) ✗ vows test/spdy-push-test.js --spec

♢ SPDY/basic test

spdy.createServer
✓ should return spdy.Server instance
Listening on this server instance
✓ should be successfull
Calling spdy.createZLib
✓ should return instance of spdy.ZLib
Creating new connection to this server
✓ should receive connect event
Creating parser and waiting for SYN_REPLY
✓ should end up w/ that frame
Sending control SYN_STREAM frame should be successfull and sending request body
✓ should emit data and end events on request
Creating parser and waiting for Data packet
✓ should end up with the push frame
When calling server.close
✓ all connections will be dropped

✓ OK » 8 honored (0.033s)
I will pick back up there tomorrow trying to get both suites passing at the same time. If I can do that, I ought to have a fairly re-usable solution for SPDY server push. Of course, that is a big "if".



Day #42

Sunday, June 5, 2011

Pushing Multiple Items with SPDY

‹prev | My Chain | next›

With my spike on SPDY server push finally finding some measure of success, I am almost ready to move on to some real code. But first, I would like to try pushing out more than one resource.

In my spike, I have been pushing out a dummy stylesheet. The easiest way that I can think to push out two resources (and verify that it is working) is to push out the real stylesheet, which includes:
section#main {
//...
background: url(spdy.jpg) no-repeat 50% 50%;
//...
}
If I can push out multiple resources with the page request, then I should be able to push out everything needed to render the node-spdy sample page with only a single request from the browser.

First up, I do a little clean-up. I will need to set multiple push streams, so I cannot hard code information in the push stream class. As noted yesterday, the only information that I believe truly changes between push streams is the URL, so I add URL to the push stream constructor:
exports.createPushStream = function(cframe, c, url) {
return new PushStream(cframe, c, url);
};
With that, I can rewrite the named-in-a-spike pushStuff() method to:
Response.prototype.pushStuff = function() {
if (this._pushed) return false;
if (this.streamID != 1) return false;

// TODO: Combine FIN & write? (once push stream is working)

var data = fs.readFileSync('pub/style.css', 'utf8');

var push_stream = createPushStream(this.cframe, this.c, "https://localhost:8081/style.css");

push_stream.write(
// "h1 { color: orange }"
data
);
push_stream.end();

this._pushed = true;
};
I have also commented out the dummy data for the stylesheet. Instead I am now reading the real one from the filesystem (blocking, I will worry about async another day).

After verifying that everything still works, I factor the actual push out into a separate method:
Response.prototype.pushStuff = function() {
if (this._pushed) return false;
if (this.streamID != 1) return false;

this._push("pub/style.css", "https://localhost:8081/style.css");

this._pushed = true;
};

Response.prototype._push = function(filename, url) {
var push_stream = createPushStream(this.cframe, this.c, url);

push_stream.write(fs.readFileSync(filename, 'utf8'));

// TODO: Combine FIN & write? (once push stream is working)
push_stream.end();
};
That will allow me to add a second push, this time for the background JPG image:
Response.prototype.pushStuff = function() {
if (this._pushed) return false;
if (this.streamID != 1) return false;

this._push("pub/style.css", "https://localhost:8081/style.css");
this._push("pub/spdy.jpg", "https://localhost:8081/spdy.jpg");

this._pushed = true;
};
Now, when I load the page and check things out in Chrome's about:net-internals SPDY tab, I find (my notes inline):
t=1307330730921 [st=     0] +SPDY_SESSION  [dt=?]
--> host = "localhost:8081"
--> proxy = "DIRECT"
t=1307330730922 [st= 1] SPDY_SESSION_RECV_SETTINGS
--> settings = ["[0:100]"]


#####
# The HTTP Request send over SPDY
t=1307330730922 [st= 1] 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
host: localhost:8081
method: GET
scheme: https
url: /
user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.782.1 Safari/535.1
version: HTTP/1.1
--> id = 1

#####
# HTTP Response headers being delivered over SPDY
t=1307330730929 [st= 8] SPDY_SESSION_SYN_REPLY
--> flags = 0
--> accept-ranges: bytes
cache-control: public, max-age=0
connection: keep-alive
content-length: 698
content-type: text/html; charset=UTF-8
etag: "698-1306200491000"
last-modified: Tue, 24 May 2011 01:28:11 GMT
status: 200 OK
version: HTTP/1.1
--> id = 1

#####
# Headers for the CSS being pushed
t=1307330730954 [st= 33] SPDY_SESSION_PUSHED_SYN_STREAM
--> associated_stream = 1
--> flags = 2
--> status: 200
url: https://localhost:8081/style.css
version: http/1.1
--> id = 2

#####
# Data for the CSS
t=1307330730955 [st= 34] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 347
--> stream_id = 2


#####
# Data FIN for the CSS
t=1307330730955 [st= 34] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 2


#####
# Headers for the JPEG image being pushed
t=1307330730955 [st= 34] SPDY_SESSION_PUSHED_SYN_STREAM
--> associated_stream = 1
--> flags = 2
--> status: 200
url: https://localhost:8081/spdy.jpg
version: http/1.1
--> id = 4
#####
# Data for the JPEG (many other packets omitted)
t=1307330730957 [st= 36] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 8184
--> stream_id = 4

#####
# Data FIN for the JPEG
t=1307330730966 [st= 45] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 4

#####
# Data for the web page itself
t=1307330730966 [st= 45] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 698
--> stream_id = 1

#####
# Data FIN for the web page itself
t=1307330730966 [st= 45] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 1

#####
# Successfully recognized push stream - yay!
t=1307330730975 [st= 54] SPDY_STREAM_ADOPTED_PUSH_STREAM
Cool! That looks to have worked.

Unfortunately, the webpage begs to differ:


(no JPEG background)

Since the SPDY tab seems quite satisfied, I guess that I am doing something silly and (hopefully not too) subtle. I play with the order of the CSS and the JPEG image, to not avail. Next I try reading the data from the filesystem directly into a Buffer rather than reading it into a string. This is easily accomplished by omitting the 'utf8' from the calls to fs.readFileSync():
Response.prototype._push = function(filename, url) {
var push_stream = createPushStream(this.cframe, this.c, url);

push_stream.write(fs.readFileSync(filename));

// TODO: Combine FIN & write? (once push stream is working)
push_stream.end();
};
That actually makes a certain amount of sense as an explanation for my trouble. Encoding a JPEG as a UTF-8 string may not produce the desired effects. In fact, that turns out to be the explanation:



Nice!

I think tomorrow I will dump my spike and begin coding this push stuff up for real.


Day #42

Saturday, June 4, 2011

Minimal Headers Needed for SPDY Server Push

‹prev | My Chain | next›

I finally got server push in SPDY working last night. Today, I hope to get it working well.

I ended up with a bunch of headers in my server push fork of node-spdy. Most were in there as vain attempts to get server push working:
   this._headers = {
"cache-control": "public, max-age=0",
url: "https://localhost:8081/style.css",
"status": 200,
"version": "http/1.1",
"content-length": 20,
"content-type": "text/css; charset=UTF-8",
etag: "347-1306200491000",
"last-modified": "Tue, 24 May 2011 01:28:11 GMT"
};
I know that status and version are required because those are the ones that finally got server push working. But what about the others?

First up, I remove everything aside from url, status and version:
   this._headers = {
url: "https://localhost:8081/style.css",
"status": 200,
"version": "http/1.1"
};
Accessing the site and checking out the SPDY tab of Chrome's about:net-internals reveals that everything is still working (my notes inline):
#####
# The client request for the web page:
t=1307239273224 [st= 1] 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
host: localhost:8081
method: GET
scheme: https
url: /
user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.782.1 Safari/535.1
version: HTTP/1.1
--> id = 1

#####
# Settings, currently improperly implemented in Chrome:
t=1307239273232 [st= 9] SPDY_SESSION_RECV_SETTINGS
--> settings = ["[0:100]"]

#####
# Replying with the home page headers:
t=1307239273264 [st=41] SPDY_SESSION_SYN_REPLY
--> flags = 0
--> accept-ranges: bytes
cache-control: public, max-age=0
connection: keep-alive
content-length: 698
content-type: text/html; charset=UTF-8
etag: "698-1306200491000"
last-modified: Tue, 24 May 2011 01:28:11 GMT
status: 200 OK
version: HTTP/1.1
--> id = 1

#####
# The push stream
t=1307239273264 [st=41] SPDY_SESSION_PUSHED_SYN_STREAM
--> associated_stream = 1
--> flags = 2
--> status: 200
url: https://localhost:8081/style.css
version: http/1.1
--> id = 2

#####
# Push stream data
t=1307239273264 [st=41] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 20
--> stream_id = 2

#####
# FIN data omitted

#####
# Home page data
t=1307239273265 [st=42] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 698
--> stream_id = 1

#####
# It's a legit push stream!
t=1307239273274 [st=51] SPDY_STREAM_ADOPTED_PUSH_STREAM

#####
# A second request from the browser (POSTing AJAX)
t=1307239273313 [st=90] SPDY_SESSION_SYN_STREAM
--> flags = 0
--> 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
content-length: 18
content-type: application/xml
host: localhost:8081
method: POST
origin: https://localhost:8081
referer: https://localhost:8081/
scheme: https
url: /
user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.782.1 Safari/535.1
version: HTTP/1.1
--> id = 3
OK. So the minimally required values set for SPDY server push to work with Chrome are:
  • status—this is an HTTP status. Why this would be anything other than 200 in a push stream is beyond me. Regardless, it is required.
  • version—the version of HTTP over SPDY being used. Why this would be anything other than HTTP/1.1 is beyond me. Regardless, it is required.
  • url—the fully qualified URL of the resource being pushed.
What strikes me as strange about this is that draft 3 of the SPDY spec seems to indicate that host, scheme, etc. are required as well:
The pushed stream inherits all of the headers from the associated-stream-id with the exception of ":host", ":scheme", and ":path", which are provided as part of the pushed response stream headers.
Clearly one can derive this information from the fully qualified URL. But does it work to replace the URL with these attributes?
  this._headers = {
"status": 200,
"version": "http/1.1",
//url: "https://localhost:8081/style.css"
method: "GET",
scheme: "https",
host: "localhost:8081",
path: "/style.css"
};
The answer, it turns out, is "no":
t=1307245599194 [st= 40]     SPDY_SESSION_PUSHED_SYN_STREAM  
--> associated_stream = 1
--> flags = 2
--> host: localhost:8081
method: GET
path: /style.css
scheme: https
status: 200
version: http/1.1
--> id = 2
t=1307245599195 [st= 41] SPDY_SESSION_SEND_RST_STREAM
--> status = 1
--> stream_id = 2
The scheme, host, and path for which the spec calls definitely do not work with Chrome, which replies immediately with a RST_STREAM. More specifically, a PROTOCOL_ERROR:
1 - PROTOCOL_ERROR. This is a generic error, and should only be used if a more specific error is not available.
Interesting.

The only other thing that I would like to verify is that I cannot get away with a relative URL. It is a bit of a hassle to include the domain name in the URL. In real life, this might need to work in development, staging and production environments. Sure, I can grab the scheme and host from the associated stream, but if I do not have to...

Unfortunately, I do have to:
t=1307208760541 [st=     39]     SPDY_SESSION_PUSHED_SYN_STREAM  
--> associated_stream = 1
--> flags = 2
--> host: localhost:8081
method: GET
scheme: https
status: 200
url: /style.css
version: http/1.1
--> id = 2
t=1307208760541 [st= 39] SPDY_SESSION_SEND_RST_STREAM
--> status = 1
--> stream_id = 2
...
t=1307208760551 [st= 49] SPDY_SESSION_SYN_STREAM
--> flags = 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
host: localhost:8081
method: GET
referer: https://localhost:8081/
scheme: https
url: /style.css
user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.782.1 Safari/535.1
version: HTTP/1.1
--> id = 3
Ah well. I now have the minimal set of headers required to make SPDY server push work with Chrome. That is a fine stopping point for today.

Day #41

Friday, June 3, 2011

SPDY Server Push

‹prev | My Chain | next›

Thanks to an assist from Mike Belshe (OK not so much an assist, more he solved it completely), I now have server push working in node-spdy.

This is just a spike at this point and not yet general purpose. When the client connects to the node-spdy server, I am trying to server push a dumb version of the CSS stylesheet. As Mike pointed out, I was missing version and status in the push stream's headers.

I had experimented with a number of headers. Per the spec:
The pushed stream inherits all of the headers from the associated-stream-id with the exception of ":host", ":scheme", and ":path", which are provided as part of the pushed response stream headers.
I completely overlooked the part of the spec describing responses (push or otherwise):
The response status line is unfolded into name/value pairs like other HTTP headers and must be present:
":status" - The HTTP response status code (e.g. "200" or "200 OK")
":version" - The HTTP response version (e.g. "HTTP/1.1")
So I go ahead and add this to my dumb, push version of the /style.css stylesheet in the node-spdy sample app:
var PushStream = exports.PushStream = function(cframe, c) {
stream.Stream.call(this);
this.streamID = 2; // TODO auto-increment even numbers per: http://www.chromium.org/spdy/spdy-protocol/spdy-protocol-draft2#TOC-Stream-creation

this.associatedStreamId = cframe.data.streamID;
this.c = c;

this._headers = {
"cache-control": "public, max-age=0",
url: "https://localhost:8081/style.css",
"status": 200,
"version": "http/1.1",

"content-length": 20,
"content-type": "text/css; charset=UTF-8",
etag: "347-1306200491000",
"last-modified": "Tue, 24 May 2011 01:28:11 GMT"
};
};
Now, when I load up the sample node-spdy app, I see:



That is definitely the dumb version of the /style.css stylesheet in effect:
  push_stream.write(
"h1 { color: orange }"
);
Taking a look at this in the SPDY tab of about:net-internals, I see that my push stream is adopted by Chrome:

t=1307160566672 [st= 0] +SPDY_SESSION  [dt=?]
--> host = "localhost:8081"
--> proxy = "DIRECT"
t=1307160566672 [st= 0] SPDY_SESSION_RECV_SETTINGS
--> settings = ["[0:100]"]
t=1307160566672 [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
host: localhost:8081
method: GET
scheme: https
url: /
user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.782.1 Safari/535.1
version: HTTP/1.1
--> id = 1
t=1307160566677 [st= 5] SPDY_SESSION_SYN_REPLY
--> flags = 0
--> accept-ranges: bytes
cache-control: public, max-age=0
connection: keep-alive
content-length: 698
content-type: text/html; charset=UTF-8
etag: "698-1306200491000"
last-modified: Tue, 24 May 2011 01:28:11 GMT
status: 200 OK
version: HTTP/1.1
--> id = 1
t=1307160566711 [st=39] SPDY_SESSION_PUSHED_SYN_STREAM
--> associated_stream = 1
--> flags = 2
--> cache-control: public, max-age=0
content-length: 20
content-type: text/css; charset=UTF-8
etag: 347-1306200491000
last-modified: Tue, 24 May 2011 01:28:11 GMT
status: 200
url: https://localhost:8081/style.css
version: http/1.1
--> id = 2
t=1307160566711 [st=39] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 20
--> stream_id = 2
...
The new status and version are in place and seem to be making the difference.

After receiving the pushed CSS as well as the HTML for the page itself, Chrome notes that yes, it really is a legit push stream:
t=1307160566714 [st=42]     SPDY_STREAM_ADOPTED_PUSH_STREAM  
That is not new. I had node-spdy that far days ago. What is new is that, since I have all of the necessary headers in place, Chrome does not block waiting on a HEADERS SPDY frame. Instead, it makes the next request (an AJAX POST):
t=1307160566721 [st=49]     SPDY_SESSION_SYN_STREAM  
--> flags = 0
--> 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
content-length: 18
content-type: application/xml
host: localhost:8081
method: POST
origin: https://localhost:8081
referer: https://localhost:8081/
scheme: https
url: /
user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.782.1 Safari/535.1
version: HTTP/1.1
--> id = 3
After sending the headers for that request, Chrome sends the POST data itself:
t=1307160566723 [st=51]     SPDY_SESSION_SEND_DATA  
--> flags = 1
--> size = 18
--> stream_id = 3
The server replies with header and data:
t=1307160566725 [st=53]     SPDY_SESSION_SYN_REPLY  
--> flags = 0
--> connection: keep-alive
status: 200 OK
version: HTTP/1.1
--> id = 3
t=1307160566761 [st=89] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 18
--> stream_id = 3
t=1307160566761 [st=89] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 3
And that is it.

The most important aspect of this SPDY session is that the browser never requests the CSS stylesheet. The page itself definitely includes the CSS:
<!DOCTYPE html> 
<html>
<head>
<link rel=icon type=image/png href="favicon.png" />
<link rel=stylesheet type=text/css href="style.css" />

<title>SPDY Server</title>
...
But since the server performed a SPDY server push, the client recognizes that the resource in question has already been pushed into cache, making a request unnecessary.

And, if I shift-reload the page, I by-pass cache and download the real stylesheet for the node-spdy sample app:




Yay! SPDY server push is finally mine!


Day #39

Setting Up Node-SPDY

‹prev | My Chain | next›

Up tonight, I try to get my branch of node-spdy up and running on my http://eeecomputes.com Linode. I need to get it running so that the spdy-dev mailing list (specifically Mike Belshe) can help troubleshoot my server push woes.

SPDY requires the relatively new NPN (Next Protocol Negotiation) extension to SSL. So, first up, I install the latest openssl:
cd ~/src/
wget ftp://ftp.openssl.org/snapshot/openssl-SNAP-20110603.tar.gz
tar zxf openssl-SNAP-20110603.tar.gz
cd openssl-SNAP-20110603
Note: I install tarballs in $HOME/src as opposed to $HOME/repos. I reserve the latter for code under source code management.

Note #2: The openssl snapshots are only available for a rolling window of 4 days. In the future, I will check out ftp://ftp.openssl.org/snapshot/ for the most recent snapshot. This is a slight inconvenience, but beats installing CVS.

Next, I configure openssl using the Ubuntu configuration settings that I found worked for 32 and 64 bit:
./Configure shared --prefix=$HOME/local no-idea no-mdc2 no-rc5 zlib  enable-tlsext linux-elf
make depend
make
make install
I install locally, not wanting to mess up the other stuff I have going on that server. To access, I add the following to my .bashrc:
# For locally installed binaries
export LD_LIBRARY_PATH=$HOME/local/lib
PATH=$HOME/local/bin:$PATH
PKG_CONFIG_PATH=$HOME/local/lib/pkgconfig
CPATH=$HOME/local/include
export MANPATH=$HOME/local/share/man:/usr/share/man

# For node.js work. For more info, see:
# http://blog.nodejs.org/2011/04/04/development-environment/
for i in $HOME/local/*; do
[ -d $i/bin ] && PATH="${i}/bin:${PATH}"
[ -d $i/sbin ] && PATH="${i}/sbin:${PATH}"
[ -d $i/include ] && CPATH="${i}/include:${CPATH}"
[ -d $i/lib ] && LD_LIBRARY_PATH="${i}/lib:${LD_LIBRARY_PATH}"
[ -d $i/lib/pkgconfig ] && PKG_CONFIG_PATH="${i}/lib/pkgconfig:${PKG_CONFIG_PATH}"
[ -d $i/share/man ] && MANPATH="${i}/share/man:${MANPATH}"
done
Next up, I install node.js. NPN is not in the most recent version of node.js (0.4.8), so I have to install the pre-release from github:
cd ~/repos/
git clone https://github.com/joyent/node.git
cd node
Then I configure and install node:
./configure --openssl-includes=$HOME/local/include --openssl-libpath=$HOME/local/lib --prefix=$HOME/local/node-v0.5.0-pre
make
make install
It needs to be configured so that it uses the NPN-enabled openssl that I just installed in my ~/local directory. It also needs to be configured to install into a ~/local sub-directory (which will be picked up by my new .bashrc paths).

I then install npm and the required connect and zlibcontext packages:
curl http://npmjs.org/install.sh | sh
npm install zlibcontext
npm install connect
Lastly, I clone my node-spdy repository (and checkout the push-stream branch where I have been experimenting with SPDY push streams):
git clone git://github.com/eee-c/node-spdy.git
git checkout -b push-stream -t origin/push-stream
With that, I can change directory into node-spdy and fire up the test server:
cd node-spdy
node ./test/spdy-server.js
TLS NPN Server is running on port : 8081
And that is all there is to it.

Day #39

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

Wednesday, June 1, 2011

Compressing SPDY DATA Frames

‹prev | My Chain | next›

Tonight I take a break from my SPDY server push frustrations to look at DATA frame compression. Per recent discussion the SPDY-dev mailing list, this is something that is likely to be removed from the spec (it's just as easy to do gzip compression over HTTP as it is to compress at the SPDY framing layer). Still, I am curious. And it beats bludgeoning one's head against the server push rocks.

Per the most recent version of the SPDY spec, DATA frames can be flagged as compressed with 0x02:
0x02 = FLAG_COMPRESS - indicates that the data in this frame has been compressed.
Lucky for me, node-spdy already supports this in the DATA frame:
exports.createDataFrame = function(zlib, headers, data) {
if (headers.flags & enums.DATA_FLAG_COMPRESSED) {
data = zlib.deflate(data);
}

//...
};
It should be a simple matter of updating the Response class to send in DATA_FLAG_COMPRESSED (when not a DATA FIN):
Response.prototype._write = function(data, encoding, fin) {
//...

var dframe = createDataFrame(this.c.zlib, {
streamID: this.streamID,
flags: fin ? enums.DATA_FLAG_FIN : enums.DATA_FLAG_COMPRESSED,
}, Buffer.isBuffer(data) ? data : new Buffer(data, encoding));

//...
};
With that, I load up the sample server in Chrome and am very quickly greeted by:



Yikes!

I cannot look on the about:net-internals SPDY tab for this session because it is not active. Instead, I go onto the Events tab and filter by type:SPDY_SESSION. I find the following:
t=1306983317971 [st=36]     SPDY_SESSION_SYN_REPLY  
--> flags = 0
--> accept-ranges: bytes
cache-control: public, max-age=0
connection: keep-alive
content-length: 698
content-type: text/html; charset=UTF-8
etag: "698-1306200491000"
last-modified: Tue, 24 May 2011 01:28:11 GMT
status: 200 OK
version: HTTP/1.1
--> id = 1
t=1306983317973 [st=38] SPDY_SESSION_CLOSE
--> status = -337
t=1306983317973 [st=38] SPDY_SESSION_POOL_REMOVE_SESSION
--> session = {"id":3982,"type":6}
Double yikes!

Chrome sees the SYN_REPLY containing the headers for the home page, but the compressed data response is nowhere to be found. That means that it is back to Wireshark for packet inspection.

There, I find my SYN_REPLY:
                +------------------------------------+
80 02 00 02 |1| version | 2 |
+------------------------------------+
00 00 00 a4 | Flags (8) | Length (24 bits) |
+------------------------------------+
00 00 00 01 |X| Stream-ID (31bits) |
+------------------------------------+
00 00 78 bb | Number of Name/Value pairs (int32) |
df a2 51 b2 +------------------------------------+
62 e0 64 e0 | Compressed Name/Value pairs |
42 c4 10 03
57 76 6a 6a
81 6e 62 4e 66 59 2a 03 1f 6a 90 33 30 9b 59 5a
30 f0 a2 c4 2d 83 20 c4 1d 3a 0a 50 97 d8 1a 30
f0 a2 04 2e 83 2c 30 38 75 14 8c 4c 14 80 c1 a3
00 cc 0b 86 0a 06 86 56 46 16 56 40 86 bb 6f 08
03 0b 28 56 18 84 95 80 66 eb 02 b3 84 19 30 c3
98 58 02 f3 8e 81 12 03 0f 72 e4 31 48 c0 c3 cf
5a 01 e6 df d0 10 37 5d a0 93 50 d2 3b 03 6b 52
65 09 90 62 83 78 95 81 0d 68 a2 82 bf 37 03 3b
d4 d3 0c 1c b0 b0 00 00 00 00 ff ff
This is followed by the SYN_REPLY's DATA packet (which contains the homepage):
             +----------------------------------+
00 00 00 01 |C| Stream-ID (31bits) |
+----------------------------------+
02 00 01 7b | Flags (8) | Length (24 bits) |
+----------------------------------+
5c 55 4d 6f | Data |
82 40 10 bd +----------------------------------+
fb 2b 9e 5c
c0 a4 81 98
f4 26 eb a1
d5 c4 26 7e
a5 70 a8 c7 16 d6 b0 8a 40 d9 45 4b 1a ff 7b 67
d9 95 90 5e 74 98 7d f3 f9 66 76 c3 f1 62 f7 1a
1f f6 4b 68 af f3 51 68 fe 80 50 df 4a 5a 20 31
17 c5 19 35 cf 99 a0 6c a0 33 61 3d 7f c8 68 ef
99 73 fc bc ea 43 9f 34 0e 82 ff 76 52 b5 39 97
19 4d 9f b1 ee ca 48 a4 b4 c6 dd b1 4f df 9d a9
b1 55 42 e5 7c 1e ed 17 07 44 dd 2e 86 81 51 e9
dc 82 47 72 e1 57 99 b6 36 9a 34 f4 41 a4 ec 42
c3 61 b4 ba 90 29 12 a2 43 32 63 bf 2d 53 ee 9f
24 e2 75 84 ed 7e 8b 2e 84 59 77 9c 1a a9 70 2b
eb b3 1c 53 8c 69 ef 22 15 57 ed d6 72 d1 ab 03
d2 db e0 81 8d fe 48 5f 26 b5 a8 7a 24 dd 23 f8
c9 6a 30 14 fc 86 8f cd 7a a5 54 f5 ce bf 69 c9
94 37 99 8d 2c 8c 20 7e 59 f1 c2 73 f7 bb 28 76
9f e0 06 f4 a3 ea 86 13 66 00 29 6a 2a bf d5 dc
ea a9 27 c2 c9 f1 b1 29 ba 04 bc 09 7e 2d 16 10
47 78 da a2 c3 47 1a 0f c6 18 9e 87 18 20 2d 93
e6 42 75 f9 f4 16 2d 73 ae c5 97 f6 2d f5 5c 5b
af 3b f1 05 2d 47 bd 8a 37 6b 8a 64 1c ca 8a 1e
2f 1e 13 91 b3 de d5 dd 4a f7 61 b6 92 17 a9 e7
64 9c ee 4b e8 e7 c8 f6 7a ec d8 9a a8 75 83 5e
3d 1a 87 d1 f0 08 1d e9 86 eb 30 30 23 fa 07 00
00 ff ff
Note the flag is, indeed set to 0x02, so hopefully the compression has worked.

Dropping into my familiar node REPL, I set up my zlib-context (used by SPDY to compress/decompress):
var Buffer = require('buffer').Buffer,
ZLibContext = require('zlibcontext').ZLibContext;

// SPDY dictionary
var flatDictStr = [
'optionsgetheadpostputdeletetraceacceptaccept-charsetaccept-encodingaccept-',
'languageauthorizationexpectfromhostif-modified-sinceif-matchif-none-matchi',
'f-rangeif-unmodifiedsincemax-forwardsproxy-authorizationrangerefererteuser',
'-agent10010120020120220320420520630030130230330430530630740040140240340440',
'5406407408409410411412413414415416417500501502503504505accept-rangesageeta',
'glocationproxy-authenticatepublicretry-afterservervarywarningwww-authentic',
'ateallowcontent-basecontent-encodingcache-controlconnectiondatetrailertran',
'sfer-encodingupgradeviawarningcontent-languagecontent-lengthcontent-locati',
'oncontent-md5content-rangecontent-typeetagexpireslast-modifiedset-cookieMo',
'ndayTuesdayWednesdayThursdayFridaySaturdaySundayJanFebMarAprMayJunJulAugSe',
'pOctNovDecchunkedtext/htmlimage/pngimage/jpgimage/gifapplication/xmlapplic',
'ation/xhtmltext/plainpublicmax-agecharset=iso-8859-1utf-8gzipdeflateHTTP/1',
'.1statusversionurl'
].join(''),
flatDict = new Buffer(flatDictStr.length + 1);

flatDict.write(flatDictStr, 'ascii');
flatDict[flatDict.length - 1] = 0;

var context = new ZLibContext(flatDict);
Then I decompress the Name/Value data from the first packet:
var octets1 = [
0x78, 0xbb,
0xdf, 0xa2, 0x51, 0xb2, 0x62, 0xe0, 0x64, 0xe0, 0x42, 0xc4, 0x10, 0x03, 0x57, 0x76, 0x6a, 0x6a,
0x81, 0x6e, 0x62, 0x4e, 0x66, 0x59, 0x2a, 0x03, 0x1f, 0x6a, 0x90, 0x33, 0x30, 0x9b, 0x59, 0x5a,
0x30, 0xf0, 0xa2, 0xc4, 0x2d, 0x83, 0x20, 0xc4, 0x1d, 0x3a, 0x0a, 0x50, 0x97, 0xd8, 0x1a, 0x30,
0xf0, 0xa2, 0x04, 0x2e, 0x83, 0x2c, 0x30, 0x38, 0x75, 0x14, 0x8c, 0x4c, 0x14, 0x80, 0xc1, 0xa3,
0x00, 0xcc, 0x0b, 0x86, 0x0a, 0x06, 0x86, 0x56, 0x46, 0x16, 0x56, 0x40, 0x86, 0xbb, 0x6f, 0x08,
0x03, 0x0b, 0x28, 0x56, 0x18, 0x84, 0x95, 0x80, 0x66, 0xeb, 0x02, 0xb3, 0x84, 0x19, 0x30, 0xc3,
0x98, 0x58, 0x02, 0xf3, 0x8e, 0x81, 0x12, 0x03, 0x0f, 0x72, 0xe4, 0x31, 0x48, 0xc0, 0xc3, 0xcf,
0x5a, 0x01, 0xe6, 0xdf, 0xd0, 0x10, 0x37, 0x5d, 0xa0, 0x93, 0x50, 0xd2, 0x3b, 0x03, 0x6b, 0x52,
0x65, 0x09, 0x90, 0x62, 0x83, 0x78, 0x95, 0x81, 0x0d, 0x68, 0xa2, 0x82, 0xbf, 0x37, 0x03, 0x3b,
0xd4, 0xd3, 0x0c, 0x1c, 0xb0, 0xb0, 0x00, 0x00, 0x00, 0x00, 0xff, 0xff];

var d1 = new Buffer(octets1);
var nv1 = context.inflate(d1);
nv1.toString();
'\u0000\t\u0000\nconnection\u0000\nkeep-alive\u0000\u000econtent-length\u0000\u0003698\u0000\rcache-control\u0000\u0011public, max-age=0\u0000\rlast-modified\u0000\u001dTue, 24 May 2011 01:28:11 GMT\u0000\u0004etag\u0000\u0013"698-1306200491000"\u0000\fcontent-type\u0000\u0018text/html; charset=UTF-8\u0000\raccept-ranges\u0000\u0005bytes\u0000\u0006status\u0000\u0006200 OK\u0000\u0007version\u0000\bHTTP/1.1'
That looks to match up with what I saw in the Chrome's version of the SPDY session. Next, I decompress the DATA frame (re-using the same zlib-context):
var octets2 = [
0x5c, 0x55, 0x4d, 0x6f, 0x82, 0x40, 0x10, 0xbd,
0xfb, 0x2b, 0x9e, 0x5c, 0xc0, 0xa4, 0x81, 0x98, 0xf4, 0x26, 0xeb, 0xa1, 0xd5, 0xc4, 0x26, 0x7e,
0xa5, 0x70, 0xa8, 0xc7, 0x16, 0xd6, 0xb0, 0x8a, 0x40, 0xd9, 0x45, 0x4b, 0x1a, 0xff, 0x7b, 0x67,
0xd9, 0x95, 0x90, 0x5e, 0x74, 0x98, 0x7d, 0xf3, 0xf9, 0x66, 0x76, 0xc3, 0xf1, 0x62, 0xf7, 0x1a,
0x1f, 0xf6, 0x4b, 0x68, 0xaf, 0xf3, 0x51, 0x68, 0xfe, 0x80, 0x50, 0xdf, 0x4a, 0x5a, 0x20, 0x31,
0x17, 0xc5, 0x19, 0x35, 0xcf, 0x99, 0xa0, 0x6c, 0xa0, 0x33, 0x61, 0x3d, 0x7f, 0xc8, 0x68, 0xef,
0x99, 0x73, 0xfc, 0xbc, 0xea, 0x43, 0x9f, 0x34, 0x0e, 0x82, 0xff, 0x76, 0x52, 0xb5, 0x39, 0x97,
0x19, 0x4d, 0x9f, 0xb1, 0xee, 0xca, 0x48, 0xa4, 0xb4, 0xc6, 0xdd, 0xb1, 0x4f, 0xdf, 0x9d, 0xa9,
0xb1, 0x55, 0x42, 0xe5, 0x7c, 0x1e, 0xed, 0x17, 0x07, 0x44, 0xdd, 0x2e, 0x86, 0x81, 0x51, 0xe9,
0xdc, 0x82, 0x47, 0x72, 0xe1, 0x57, 0x99, 0xb6, 0x36, 0x9a, 0x34, 0xf4, 0x41, 0xa4, 0xec, 0x42,
0xc3, 0x61, 0xb4, 0xba, 0x90, 0x29, 0x12, 0xa2, 0x43, 0x32, 0x63, 0xbf, 0x2d, 0x53, 0xee, 0x9f,
0x24, 0xe2, 0x75, 0x84, 0xed, 0x7e, 0x8b, 0x2e, 0x84, 0x59, 0x77, 0x9c, 0x1a, 0xa9, 0x70, 0x2b,
0xeb, 0xb3, 0x1c, 0x53, 0x8c, 0x69, 0xef, 0x22, 0x15, 0x57, 0xed, 0xd6, 0x72, 0xd1, 0xab, 0x03,
0xd2, 0xdb, 0xe0, 0x81, 0x8d, 0xfe, 0x48, 0x5f, 0x26, 0xb5, 0xa8, 0x7a, 0x24, 0xdd, 0x23, 0xf8,
0xc9, 0x6a, 0x30, 0x14, 0xfc, 0x86, 0x8f, 0xcd, 0x7a, 0xa5, 0x54, 0xf5, 0xce, 0xbf, 0x69, 0xc9,
0x94, 0x37, 0x99, 0x8d, 0x2c, 0x8c, 0x20, 0x7e, 0x59, 0xf1, 0xc2, 0x73, 0xf7, 0xbb, 0x28, 0x76,
0x9f, 0xe0, 0x06, 0xf4, 0xa3, 0xea, 0x86, 0x13, 0x66, 0x00, 0x29, 0x6a, 0x2a, 0xbf, 0xd5, 0xdc,
0xea, 0xa9, 0x27, 0xc2, 0xc9, 0xf1, 0xb1, 0x29, 0xba, 0x04, 0xbc, 0x09, 0x7e, 0x2d, 0x16, 0x10,
0x47, 0x78, 0xda, 0xa2, 0xc3, 0x47, 0x1a, 0x0f, 0xc6, 0x18, 0x9e, 0x87, 0x18, 0x20, 0x2d, 0x93,
0xe6, 0x42, 0x75, 0xf9, 0xf4, 0x16, 0x2d, 0x73, 0xae, 0xc5, 0x97, 0xf6, 0x2d, 0xf5, 0x5c, 0x5b,
0xaf, 0x3b, 0xf1, 0x05, 0x2d, 0x47, 0xbd, 0x8a, 0x37, 0x6b, 0x8a, 0x64, 0x1c, 0xca, 0x8a, 0x1e,
0x2f, 0x1e, 0x13, 0x91, 0xb3, 0xde, 0xd5, 0xdd, 0x4a, 0xf7, 0x61, 0xb6, 0x92, 0x17, 0xa9, 0xe7,
0x64, 0x9c, 0xee, 0x4b, 0xe8, 0xe7, 0xc8, 0xf6, 0x7a, 0xec, 0xd8, 0x9a, 0xa8, 0x75, 0x83, 0x5e,
0x3d, 0x1a, 0x87, 0xd1, 0xf0, 0x08, 0x1d, 0xe9, 0x86, 0xeb, 0x30, 0x30, 0x23, 0xfa, 0x07, 0x00,
0x00, 0xff, 0xff
];

var d2 = new Buffer(octets2);
var nv2 = context.inflate(d2);
nv2.toString();
'<!DOCTYPE html>\n<html>\n <head>\n <link rel=icon type=image/png href="favicon.png" />\n <link rel=stylesheet type=text/css href="style.css" />\n\n <title>SPDY Server</title>\n </head>\n <body>\n <section id=main>\n <h1 class=title>Node.js TLS NPN SPDY server just works!</h1>\n <div id=content>\n </div>\n </section>\n\n <script>\n var xhr = new XMLHttpRequest();\n\n xhr.open(\'POST\', \'/\', true);\n xhr.onreadystatechange = function() {\n if (xhr.readyState === 4) {\n document.getElementById(\'content\').innerHTML = xhr.responseText;\n }\n };\n xhr.send("hello from server!");\n </script>\n <script> \n </script> \n </body>\n</html>\n'
And that looks to be the web page that I was expecting.

The last packet that was sent back to Chrome (even though Chrome never saw the DATA packet) was an innocuous little DATA FIN:
0000   00 00 00 01 01 00 00 00
I am pretty sure that this ought to work, so I suspect that Chrome is just refusing to accept legitimately compressed DATA packets. That is not altogether unreasonable given that they are likely to go away. Still, it cuts short any investigation I might do.


Day #36