Tuesday, May 31, 2011

Failure to Launch: SPDY Server Push

‹prev | My Chain | next›

I am about to give up on SPDY server push with node-spdy. Before I do, I feel compelled to give it one more try.

I took a step back last night (I think) when I concentrated on fiddling with relative URLs in the SYN_STREAM that initiated the push stream. It seemed a reasonable thing to try given that all URLs that show up in other streams are root relative (e.g. /style.css instead of https://localhost:8081/style.css).

The magical thing that goes missing when using relative URLs is the SPDY_STREAM_ADOPTED_PUSH_STREAM that I saw two nights ago:
t=1306724141170 [st=88]     SPDY_STREAM_ADOPTED_PUSH_STREAM
To my still-in-training eye, that SPDY_STREAM_ADOPTED_PUSH_STREAM seems a good thing.

First up tonight, I fiddle with the point at which I send the data FIN on the push stream. The other night, I sent the push stream FIN immediately after sending the push stream DATA and before sending the FIN on the SYN_REPLY. Tonight, I try sending the push stream FIN after sending all of the data in the original reply (i.e. the homepage):
Response.prototype.end = function(data, encoding) {
this.writable = false;
this._write(data, encoding, true);
if (this.push_stream) {
this.push_stream.end();
}
};
Loading that up in the browser and checking the SPDY log in Chrome's about:net-internals, I find:
t=1306892767809 [st= 48]     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
url: https://localhost:8081/style.css
--> id = 2
t=1306892767809 [st= 48] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 20
--> stream_id = 2
t=1306892767810 [st= 49] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 698
--> stream_id = 1
t=1306892767810 [st= 49] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 1
t=1306892767810 [st= 49] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 2
t=1306892767879 [st=118] SPDY_STREAM_ADOPTED_PUSH_STREAM
Back to where I was the other night. I have my desired SPDY_STREAM_ADOPTED_PUSH_STREAM, but then the SPDY session just hangs.

Checking the packet specifics out with Wireshark, I see the SYN_REPLY returned:
                 +----------------------------------+
80 02 00 02 |1| 1 | 2 |
+----------------------------------+
00 00 00 a4 | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 01 |X| Stream-ID (31bits) |
+----------------------------------+
00 00 78 bb | Unused | |
df a2 51 b2 +---------------- |
62 e0 64 e0 | Name/value header block |
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
That will contain headers for the homepage. Next is the push stream's SYN_STREAM:
                 +----------------------------------+
80 02 00 01 |1| 1 | 1 |
+----------------------------------+
02 00 00 51 | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 02 |X| Stream-ID (31bits) |
+----------------------------------+
00 00 00 01 |X|Associated-To-Stream-ID (31bits)|
+----------------------------------+
00 00 62 60 | Pri | Unused | |
+------------------ |
| Name/value header block |
23 c2 37 cc | ... |
a0 40 52 c8
28 29 29 28
b6 d2 d7 07 25 b7 1c 50 a1 62 65 61 60 61 a8 5f
5c 52 99 93 aa 97 5c 5c 8c 11 56 4c 46 06 68 ee
17 07 bb 1f a8 16 dd f9 90 10 10 34 36 31 47 0d
00 d2 02 12 00 00 00 ff ff
Then comes the data for the push stream (ID = 2):
                +----------------------------------+
00 00 00 02 |C| Stream-ID (31bits) |
+----------------------------------+
00 00 00 14 | Flags (8) | Length (24 bits) |
+----------------------------------+
68 31 20 7b | Data |
20 63 6f 6c +----------------------------------+
6f 72 3a 20
6f 72 61 6e
67 65 20 7d
The data in that frame is uncompressed. Checking it out in hex+text view, I see that it is my dummy stylesheet:
0000   00 00 00 02 00 00 00 14 68 31 20 7b 20 63 6f 6c  ........h1 { col
0010 6f 72 3a 20 6f 72 61 6e 67 65 20 7d or: orange }
The next frame through is the data frame for the SYN_REPLY, the homepage:
0000   00 00 00 01 00 00 02 ba 3c 21 44 4f 43 54 59 50  ........<!DOCTYP
0010 45 20 68 74 6d 6c 3e 0a 3c 68 74 6d 6c 3e 0a 20 E html>.<html>.
...
Then, the data FIN for the SYN_REPLY:
               +----------------------------------+
00 00 00 01 |C| Stream-ID (31bits) |
+----------------------------------+
01 00 00 00 | Flags (8) | Length (24 bits) |
+----------------------------------+
| Data |
+----------------------------------+
Which is followed by the data FIN for the push stream (ID = 2):
               +----------------------------------+
00 00 00 02 |C| Stream-ID (31bits) |
+----------------------------------+
01 00 00 00 | Flags (8) | Length (24 bits) |
+----------------------------------+
| Data |
+----------------------------------+
Everything looks just as I would expect and as was shown in the SPDY log in Chrome.

If I escape/stop the blocked SPDY session, then I see the following RST_STREAM coming from the client:
               +-------------------------------+
80 02 00 03 |1| 1 | 3 |
+-------------------------------+
00 00 00 08 | Flags (8) | 8 |
+-------------------------------+
00 00 00 02 |X| Stream-ID (31bits) |
+-------------------------------+
00 00 00 05 | Status code |
+-------------------------------+
A status code of 0x05 means:
5 - CANCEL. Used by the creator of a stream to indicate that the stream is no longer needed.
Next up is the new SYN_STREAM from the client requesting the next resource:
               +----------------------------------+
80 02 00 01 |1| 1 | 1 |
+----------------------------------+
01 00 00 2f | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 03 |X| Stream-ID (31bits) |
+----------------------------------+
00 00 00 00 |X|Associated-To-Stream-ID (31bits)|
+----------------------------------+
80 00 62 e0 | Pri | Unused | |
82 c7 14 33 +------------------ |
30 cc 07 26 | Name/value header block |
b4 89 09 54 | ... |
2c 41 c8 a3
9f 96 58 96 09 8c 23 3d 60 b2 1f 14
a1 09 00 00 00 ff ff
The rest of the SPDY session is just normal SPDY as if I had never send the push stream. So fiddling with the order of data FIN seems to have no effect on things.

Next I try sending a RST_STREAM from the server in addition to the data FIN:
Response.prototype.end = function(data, encoding) {
this.writable = false;
this._write(data, encoding, true);
if (this.push_stream) {
this.push_stream.end();
this.push_stream.reset();
}
};
Reloading the page kinda-sorta works in that I see the homepage. Unfortunately, checking out the SPDY log in Chrome's about:net-internals shows that the RST_STREAM prevented the pushed stream from being "adopted". More importantly, the client ignores the pushed stylesheet and asks for it again:
t=1306896650130 [st= 41]     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
url: https://localhost:8081/style.css
--> id = 2
t=1306896650130 [st= 41] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 20
--> stream_id = 2
t=1306896650130 [st= 41] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 698
--> stream_id = 1
t=1306896650130 [st= 41] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 1
t=1306896650140 [st= 51] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 2
t=1306896650140 [st= 51] SPDY_SESSION_RST_STREAM
--> status = 5
--> stream_id = 2
t=1306896650172 [st= 83] 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
cache-control: no-cache
host: localhost:8081
method: GET
pragma: no-cache
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.772.0 Safari/535.1
version: HTTP/1.1
--> id = 3
t=1306896650177 [st= 88] SPDY_SESSION_SYN_REPLY
--> flags = 0
--> accept-ranges: bytes
cache-control: public, max-age=0
connection: keep-alive
content-length: 347
content-type: text/css; charset=UTF-8
etag: "347-1306200491000"
last-modified: Tue, 24 May 2011 01:28:11 GMT
status: 200 OK
version: HTTP/1.1
--> id = 3

t=1306896650177 [st= 88] SPDY_SESSION_RECV_DATA
Unfortunately, I do not see anything in the dump that give me hope. I do see the server-generated RST_STREAM:

+-------------------------------+
80 02 00 03 |1| 1 | 3 |
+-------------------------------+
00 00 00 08 | Flags (8) | 8 |
+-------------------------------+
00 00 00 02 |X| Stream-ID (31bits) |
+-------------------------------+
00 00 00 05 | Status code |
+-------------------------------+
But the very next SPDY frame is the client initiating the SYN_STREAM to request the stylesheet:

+----------------------------------+
80 02 00 01 |1| 1 | 1 |
+----------------------------------+
01 00 00 40 | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 03 |X| Stream-ID (31bits) |
+----------------------------------+
00 00 00 00 |X|Associated-To-Stream-ID (31bits)|
+----------------------------------+
40 00 62 e0 | Pri | Unused | |
85 c7 94 10 +------------------ |
38 a6 92 8b | Name/value header block |
8b e1 81 6f | ... |
38 1c 02 9f
1d 5a 8c 32 88 83 43 df 4a 5f 1f 55
bf 3e d6 e8 e1 d2 2f 2e a9 cc 49 d5 03 06 c7 a0
88 27 00 00 00 00 ff ff
There are no stray frames floating about that might give some indication of what to try next.

So, for now, I will shut down my direct effort to get SPDY server push working. I will keep working it in the background (along with ruby zlib), but will pick back up tomorrow by taking a closer look at compression in SPDY.


Day #35

Monday, May 30, 2011

Bad Combination: Relative URLs and SPDY Server Push

‹prev | My Chain | next›

Continuing my effort to get SPDY server push working, I make a couple of changes in the hopes that they will push me through.

Specifically, I switch from a fully qualified URL to a root relative URL for the stylesheet that I am trying to push:
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 = {
url: "/style.css"
};
};
Also, I prevent the response from sending out more than one server push:
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 push_stream = createPushStream(this.cframe, this.c);
push_stream.write(
"h1 { color: orange }"
);
push_stream.end();

this._pushed = true;
};
With that, I hope to have pushed past the never-ending server push from last night. Unfortunately, Chrome's SPDY tab in about:net-internals reports:
t=1306807793087 [st=      0] +SPDY_SESSION  [dt=4245683]
--> host = "localhost:8081"
--> proxy = "DIRECT"
t=1306807793087 [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: localhost:8081
method: GET
pragma: no-cache
scheme: https
url: /
user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.772.0 Safari/535.1
version: HTTP/1.1
--> id = 1
t=1306807793098 [st= 11] SPDY_SESSION_RECV_SETTINGS
--> settings = ["[0:100]"]
t=1306807793135 [st= 48] 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=1306807793136 [st= 49] SPDY_SESSION_PUSHED_SYN_STREAM
--> associated_stream = 1
--> flags = 2
--> url: /style.css
--> id = 2
t=1306807793136 [st= 49] SPDY_SESSION_SEND_RST_STREAM
--> status = 1
--> stream_id = 2
Bummer.

That bit about the RST_STREAM at the end of the session would seem to indicate that I was closer to having this working last night than I am today. Even more worrisome is the status with which it is failing. A 0x01 is a generic, can't help you failure:
1 - PROTOCOL_ERROR. This is a generic error, and should only be used if a more specific error is not available.
Greeaaaaat.

To make sure that there is nothing unexpected going on in there, I inspect the packets themselves using Wireshark. First up is the initial SYN_STREAM push:

+----------------------------------+
80 02 00 01 |1| 1 | 1 |
+----------------------------------+
02 00 00 27 | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 02 |X| Stream-ID (31bits) |
+----------------------------------+
00 00 00 01 |X|Associated-To-Stream-ID (31bits)|
+----------------------------------+
00 00 62 60 | Pri | Unused | |
64 60 06 05 +------------------ |
01 97 7e 71 | Name/value header block |
49 65 4e aa | ... |
5e 72 71 31
00 00 00 ff
ff 02 00 00 00 ff ff
That looks OK. The stream ID is 2 (all server-side streams are even and this is the first one). The associated ID is the first client-initiated stream (the one that requested the homepage). The flag indicates that this is server push only:
0x02 = FLAG_UNIDIRECTIONAL - a stream created with this flag is already considered to be half closed to the receiver.


Next comes the actual data that I am attempting to push out and an empty DATA FIN packet:
0000  00 00 00 02 00 00 00 14  68 31 20 7b 20 63 6f 6c   ........ h1 { col
0010 6f 72 3a 20 6f 72 61 6e 67 65 20 7d or: oran ge }

0000 00 00 00 02 01 00 00 00 ........
Lastly comes the RST_STREAM from the client:
                 +-------------------------------+
80 02 00 03 |1| 1 | 3 |
+-------------------------------+
00 00 00 08 | Flags (8) | 8 |
+-------------------------------+
00 00 00 02 |X| Stream-ID (31bits) |
+-------------------------------+
00 00 00 01 | Status code |
+-------------------------------+
And yup, a generic protocol error:
1 - PROTOCOL_ERROR. This is a generic error, and should only be used if a more specific error is not available. The receiver of this error will likely abort the entire session and possibly return an error to the user.
I spend a good deal of time adding additional headers (content-length, content-type, etc). I fiddle with the DATA FIN flag a bit, but nothing I do seems to avoid the RST_STREAM.

I think tomorrow I will give the absolute URL another go. All other URLs look to be relative and it blocked the rest of the stream from completing. Still is it seemed to yield a valid server push whereas root relative URLs seem to be a dead-end.




Day #34

Sunday, May 29, 2011

My First (SPDY) Push Stream

‹prev | My Chain | next›

As of last night, I believe that I have my server push in SPDY properly formed. Properly formed, but not actually working.

Today, I try moving the push stream around a bit. Instead of initiating the push stream before the initial stream SYN_REPLY, I think I will try it after the SYN_REPLY's headers have been send.

But first, I restart my machine and break everything. Accessing the sample node-spdy app (even before my changes) results in:
➜  node-spdy  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. (tls.js:640:22)
at EventEmitter._tickCallback (node.js:175:26)
What. The.

The browser reports a simple connection refused. Refused because the server crashed.

That is not making it anywhere near node-spdy. The backtrace seems to indicate that it is failing somewhere in the SSL/TLS code. Ugh.

I am not sure where to even begin troubleshooting this one, so I try starting an incognito session—to no avail. I try reloading and waiting a very long time—to no avail.

What ends up fixing it is restarting the browser completely. Not too big a deal since Chrome remembers tabs and windows, but... still. I would prefer a better resolution than the old windows three finger salute. For now, I push that to the back of my mind in the hopes that it has not derailed me too much tonight.

Back in my push-stream branch, I move my pushStuff() method after the SYN_REPLY response has gone out:
Response.prototype._write = function(data, encoding, fin) {
if (!this._written) {
this._flushHead();
this.pushStuff();
}
//...
After restarting the server, I access the test site again. This time, I find:



Nothing. In this case, nothing is actually progress. Last night, when I tried accessing the server, I was greeted with a lovely SPDY session error message. It seems that I am no longer causing a SPDY error. Something is still going wrong though.

Checking out the session in Chrome's about:net-internals, I find:
...
t=1306724141128 [st=46] 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=1306724141128 [st=46] SPDY_SESSION_PUSHED_SYN_STREAM
--> associated_stream = 1
--> flags = 2
--> url: https://localhost:8081/style.css
--> id = 2
t=1306724141129 [st=47] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 20
--> stream_id = 2
t=1306724141129 [st=47] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 2
t=1306724141129 [st=47] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 698
--> stream_id = 1
t=1306724141129 [st=47] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 1
t=1306724141170 [st=88] SPDY_STREAM_ADOPTED_PUSH_STREAM
Oooh! That is progress. Now, Chrome is seeing a SPDY_SESSION_PUSHED_SYN_STREAM so I am definitely on the right track. Before the push stream, Chrome sees the response to the request for the homepage:
t=1306724141128 [st=46]     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
That is just normal HTTP over SPDY. The stream ID (1) is picked up from what Chrome sent in the original request.

Next up is the push stream initialization and data:
t=1306724141128 [st=46]     SPDY_SESSION_PUSHED_SYN_STREAM  
--> associated_stream = 1
--> flags = 2
--> url: https://localhost:8081/style.css
--> id = 2
t=1306724141129 [st=47] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 20
--> stream_id = 2
t=1306724141129 [st=47] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 2
This is a spike, so I am hard coding the stream ID to 2 (server initiated SPDY streams are all even). The associated stream ID is 1, indicating that the push began as a result of the request in stream #1. Also of note is that the URL of the resource is included in the pushed data. Without the URL, the browser will not know how to cache the data, which would render the server push useless.

The two push stream data packets indicate that there are 20 bytes/octets of data and that there is nothing else on this stream.

Next up, Chrome receives two data frames on the original SYN_STREAM #1. This is the original request for the HTML resource itself:
t=1306724141129 [st=47]     SPDY_SESSION_RECV_DATA  
--> flags = 0
--> size = 698
--> stream_id = 1
t=1306724141129 [st=47] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 1
Last to come through is:
t=1306724141170 [st=88]     SPDY_STREAM_ADOPTED_PUSH_STREAM  
I have no idea what that might mean. I also am at a loss to explain why there are no more requests from Chrome for the image and AJAX resources that complete the page.

To investigate, I capture packets with tcpdump and analyze with Wireshark:
➜  node-spdy git:(push-stream) sudo tcpdump -i lo -w node-spdy_2011-05-29.pcap port 8081
tcpdump: listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes
^C63 packets captured
126 packets received by filter
0 packets dropped by kernel
➜ node-spdy git:(push-stream) ✗ wireshark node-spdy_2011-05-29.pcap
After about ten seconds of waiting for the page to respond, I escape / stop the request. Looking at the results in Wireshark, I see a lot of green (decrypted packets):



Green is normally a good thing. It means that there are lots of little SPDY frames moving about doing their thing. The problem here is that most of the SPDY frames are moving about after the 10 second mark—after I escaped the request.

The first packet through is the SYN_REPLY to the request for the homepage:
                 +----------------------------------+
80 02 00 02 |1| 1 | 2 |
+----------------------------------+
00 00 00 a4 | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 01 |X| Stream-ID (31bits) |
+----------------------------------+
00 00 78 bb | Unused | |
+---------------- |
df a2 51 b2 | Name/value header block |
62 e0 64 e0 | ... |
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
Next is the push stream, identified by the stream ID (2) and the presence of an associated stream ID (1):
                 +----------------------------------+
80 02 00 01 |1| 1 | 1 |
+----------------------------------+
02 00 00 3b | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 02 |X| Stream-ID (31bits) |
+----------------------------------+
00 00 00 01 |X|Associated-To-Stream-ID (31bits)|
+----------------------------------+
00 00 62 60 | Pri | Unused | |
64 60 06 05 +------------------ |
81 42 46 49 | Name/value header block |
49 41 b1 95 | ... |
be 3e 28 31
e5 80 8a 0c 2b 0b 03 0b 43 fd e2 92
ca 9c 54 bd e4 e2 62 00 00 00 00 ff ff 02 00 00
00 ff ff
So far, so good.

Next up is the first DATA frame (the zero control bit at the beginning is the giveaway:
 00 00 00 02 01 00 00 14 68 31 20 7b 20 63 6f 6c  ........h1 { col
6f 72 3a 20 6f 72 61 6e 67 65 20 7d or: orange }
Here, I also include the ASCII representation of the data to show that this is the fake stylesheet that I am trying to push. The stream ID for this data frame is 2 (the fourth octet), so this is definitely from the push stream.

The next SPDY frame is the web page requested in the first place:
 00 00 00 01 00 00 02 ba 3c 21 44 4f 43 54 59 50  ........<!DOCTYP
45 20 68 74 6d 6c 3e 0a 3c 68 74 6d 6c 3e 0a 20 E html>.<html>.
20 3c 68 65 61 64 3e 0a 20 20 20 20 3c 6c 69 6e <head>. <lin
6b 20 72 65 6c 3d 69 63 6f 6e 20 74 79 70 65 3d k rel=icon type=
69 6d 61 67 65 2f 70 6e 67 20 68 72 65 66 3d 22 image/png href="
66 61 76 69 63 6f 6e 2e 70 6e 67 22 20 2f 3e 0a favicon.png" />.
...
Again, the fourth octet in the data frame holds the stream ID (1), so this is not part of the server push, but is just the payload for the reply to the original request.

The last frame sent from the server is a DATA FIN:
                +----------------------------------+
00 00 00 01 |C| Stream-ID (31bits) |
+----------------------------------+
01 00 00 00 | Flags (8) | Length (24 bits) |
+----------------------------------+
| Data |
+----------------------------------+
The stream ID is 1 (the reply to the original request for the homepage). There is no data in the reply (length zero), but this is not what indicates that this is the final data frame for this stream. Rather the flag of 0x01 indicates DATA_FIN.

What is missing here is a similar DATA_FIN frame for the push stream. The DATA_FIN flag is set, but perhaps that is not sufficient. Perhaps Chrome needs a separate DATA_FIN frame nowadays. I will pick up my investigation there tomorrow.


SPDY protocol (draft 2)

Day #34

Saturday, May 28, 2011

SPDY Associated Stream ID

‹prev | My Chain | next›

Today, I continue working through the SPDY server push issue in my node-spdy fork that is resulting in:



Today I am going to focus on the SYN_STREAM frames (identified by an ID of 2):
...
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
...
In the non-push conversations, the packet look like:
t=1306632639034 [st= 46]     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=1306632639035 [st= 47] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 698
--> stream_id = 1
t=1306632639035 [st= 47] SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 0
--> stream_id = 1
I start by comparing the data seen in Wireshark against the spec:
                   +----------------------------------+
80 02 00 01 |1| 1 | 1 |
+----------------------------------+
02 00 00 3b | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 02 |X| Stream-ID (31bits) |
+----------------------------------+
00 00 00 00 |X|Associated-To-Stream-ID (31bits)|
+----------------------------------+
00 01 62 60 | Pri | Unused | |
+------------------ |
64 60 06 05 | Name/value header block |
81 42 46 49 | ... |
49 41 b1 95
be 3e 28 31
e5 80 8a 0c 2b 0b 03 0b 43 fd e2 92
ca 9c 54 bd e4 e2 62 00 00 00 00 ff ff 02 00 00
00 ff ff
Ah, well that would explain it. There is no associated stream ID.

Digging through the code a bit, I find that the associated stream ID is written by the very long
function nvsToBuffer(zlib, headers, nvs) {
//...

// Insert assocStreamID for SYN_STREAM
console.log(buff);
buff.writeUInt32(assocStreamID & 0x7fffffff, 6, 'big');

console.log(buff);

//...

console.log(buff);
return buff;
};
When I reload, I find:
<Buffer 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00>
<Buffer 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00>
<Buffer 00 00 00 02 00 00 00 00 00 01 62 60 64 60 06 05 81 42 46 49 49 41 b1 95 be 3e 28 31 e5 80 8a 0c 2b 0b 03 0b 43 fd e2 92 ca 9c 54 bd e4 e2 62 00 00 00 00 ff ff 02 00 00 00 ff ff>
All right. It seems to be set as expected. So where do things go wrong?

It turns out that it is set as expected, but in the wrong place. The assembled packet looks very familiar:
<Buffer 80 02 00 01 02 00 00 3b 00 00 00 02 00 00 00 00 00 01 62 60 64 60 06 05 81 42 46 49 49 41 b1 95 be 3e 28 31 e5 80 8a 0c 2b 0b 03 0b 43 fd e2 92 ca 9c 54 bd e4 e2 62 00 00 00 00 ff ff 02 00 00 00 ff ff>
That is the same packet that I saw in Wireshark... Ah, the associated stream ID is being set, just in the wrong place:
                   +----------------------------------+
80 02 00 01 |1| 1 | 1 |
+----------------------------------+
02 00 00 3b | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 02 |X| Stream-ID (31bits) |
+----------------------------------+
00 00 00 00 |X|Associated-To-Stream-ID (31bits)|
+----------------------------------+
00 01 62 60 | Pri | Unused | |
+------------------ |
64 60 06 05 | Name/value header block |
81 42 46 49 | ... |
49 41 b1 95
be 3e 28 31
e5 80 8a 0c 2b 0b 03 0b 43 fd e2 92
ca 9c 54 bd e4 e2 62 00 00 00 00 ff ff 02 00 00
00 ff ff
As-is, it is not the associated stream ID, but the Primary flag.

I cannot quite follow the bit flipping that goes on in the nvsToBuffer method, but I can easily move the associated stream ID location back two bytes by switching this:
    buff.writeUInt32(assocStreamID & 0x7fffffff, 6, 'big');
To this:
    buff.writeUInt32(assocStreamID & 0x7fffffff, 4, 'big');
With that, I get my packet printing out as desired:
                   +----------------------------------+
80 02 00 01 |1| 1 | 1 |
+----------------------------------+
02 00 00 3b | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 02 |X| Stream-ID (31bits) |
+----------------------------------+
00 00 00 01 |X|Associated-To-Stream-ID (31bits)|
+----------------------------------+
00 00 62 60 | Pri | Unused | |
+------------------ |
64 60 06 05 | Name/value header block |
81 42 46 49 | ... |
49 41 b1 95
be 3e 28 31
e5 80 8a 0c 2b 0b 03 0b 43 fd e2 92 ca 9c 54 bd e4 e2 62 00 00 00 00 ff ff 02 00 00 00 ff ff
But the real test is the browser, does it work any better now?

Sadly, no:



Grrr... it seems that the problem is elsewhere. I will pick back up with that tomorrow, but first I will cherry-pick the associated stream ID fix back into master so that I can submit a pull request.


Day #33

Friday, May 27, 2011

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

Thursday, May 26, 2011

Spiking SPDY Server Push

‹prev | My Chain | next›

Tonight I continue to explore server push in SPDY.

First I define a very skeleton class for a push stream in node-spdy:
/**
* Initiate SYN_STREAM
*/
Response.prototype.writeHead = function(code, reasonPhrase, headers) {
// TODO: I *think* this should only be built inside this class
throw new Error("PushStream#writeHead invoked externally");
};

/**
* Write data
*/
Response.prototype.write = function(data, encoding) {
return this._write(data, encoding, false);
};

/**
* Write any data (Internal)
*/
Response.prototype._write = function(data, encoding, fin) {
throw new Error("Please implement");
};

/**
* End stream
*/
Response.prototype.end = function(data, encoding) {
this.writable = false;
return this._write(data, encoding, true);
};

/**
* Mirroring node.js default API
*/
Response.prototype.setHeader = function(name, value) {
throw new Error("Not implemented for push stream");
};

/**
* Mirroring node.js default API
*/
Response.prototype.getHeader = function(name) {
throw new Error("Not implemented for push stream");
};

/**
* Cloning node.js default API
*/
Response.prototype.removeHeader = function(name) {
throw new Error("Not implemented for push stream");
};
As indicated by the throw statements, I am an fairly certain that most of what was required for the Response class will not be needed in PushStream. Ideally just writing back the data.

Then I start to noodle things through a bit and...

But wait a second, the write method in Response is only sending out data:
Response.prototype._write = function(data, encoding, fin) {
if (!this._written) {
this._flushHead();
}
encoding = encoding || 'utf8';

if (data === undefined) {
data = new Buffer(0);
}

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

return this.c.write(dframe);

};
A reply to a HTTP request coming in over a SYN_STREAM needs both a SYN_REPLY and a DATA response. The write() method in Response is only sending the DATA frame. What about the SYN_REPLY?

Ah. I get it now. The Response class is responsible for sending out both the header and the data frame.

So I create a private _flushHead() method in PushStream (based on the method of the same name in Response):
/**
* Flush buffered head
*/
Response.prototype._flushHead = function() {
var headers = this._headers;

var cframe = createControlFrame(this.c.zlib, {
type: enums.SYN_STREAM,
flags: enums.FLAG_UNIDIRECTIONAL,
streamID: this.streamID,
assocStreamID: this.associatedStreamId
}, headers);

return this.c.write(cframe);
};
Included here is the type, which is a SYN_STREAM. The Response class had been returning a SYN_REPLY in response to an already open SYN_STREAM (e.g. one that requested the homepage). Here I am trying to initiate a server push, hence the new SYN_STREAM. Also in there is the unidirectional flags as required by SPDY server push (there will not be a back-and-forth here, just push from the server). The new stream ID and the associated ID are set in the constructor.

(Actually, after double-checking in the enums.js file, I find that it is CONTROL_FLAG_UNIDIRECTIONAL)

Another requirement of the server push spec is that the URL is set in the SYN_STREAM. Like the stream ID and associated stream ID, the headers are currently being assigned in the constructor. For this spike, I will explicitly set the URL to the stylesheet being used. If this works, the stylesheet will make its way into the browser's cache—ultimately preventing the browser from needing to request it. So, the header:
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 = {
url: "https://localhost:8081/style.css"
};
};
I think this is starting to come together. Next up, is sending the actual stylesheet data. For that, I copy the write method directly from Response:
/**
* Write any data (Internal)
*/
Response.prototype._write = function(data, encoding, fin) {
if (!this._written) {
this._flushHead();
}
encoding = encoding || 'utf8';

if (data === undefined) {
data = new Buffer(0);
}

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

return this.c.write(dframe);
};
This method writes the just crafted header (unless it has already done so). Then it builds the DATA frame and writes it back to the connect stream.

Last up tonight it doing a little work back in the Response class. The server push will be initiated back in the Response class because server push needs an associated stream ID in order to be valid. With that in mind, I define the previously stubbed Reponse#createPushStream method:
/**
* Server push
*/
Response.prototype.createPushStream = function() {
return new PushStream(this.cframe, this.c)
};
The control frame (from the original browser request) will be sufficient to determine the associated stream ID and the connect stream will provide the transport for the server push.

Tomorrow I will add the actual data and (without a doubt) perform quite a bit of debugging because I have really played fast and loose with this code tonight as I simple tried to wrap my brain around it. Even so, I am pleased with the progress tonight. I feel as though I am close to having a workable server push in SPDY.


Day #31

Wednesday, May 25, 2011

SPDY Push: A First Look

‹prev | My Chain | next›

Up tonight, I would like to start investigating server push with SPDY.

Server push in SPDY does not involve all of what web developers tend to include in the concept of server push. SPDY does not establish a mechanism to replace COMET / web sockets / long polling, etc. Some (all?) of those would be more efficient over SPDY, but SPDY more or less sticks to a replacement for HTTP in this respect.

The "less" close to HTTP refers push, which allows the server to reply multiple times to a single reply. For instance if the client request the homepage, the server can reply "sure, and while I'm at it, here are a couple of images and a few stylesheets that you'll be wanting as well". There is some potential for abuse there, which the SPDY draft spec either addresses or offers up suggestions for implementers on how to mitigate.

I will defer abuse questions to another day, but it sure would be cool to push out the image and stylesheet for the node-spdy homepage:



I am unsure exactly where to hook this into node-spdy. It is currently not easy (possible?) at the server creation level because access to the compression stream is not exposed:
  if (req.method == 'POST') {
res.writeHead(200);
req.pipe(res);
return;
}
static(req, res, function() {
res.writeHead(404);
res.end();
});
I might be able to slide in an uncompressed push here.

But first, I do a quick check of the specs written for node-spdy. First I install vows.js (globally so that the executable is in my PATH) and run the specs:
➜  node-spdy git:(master) ✗ npm install -g vows
/home/cstrom/local/node-v0.5.0-pre/bin/vows -> /home/cstrom/local/node-v0.5.0-pre/lib/node_modules/vows/bin/vows
eyes@0.1.6 /home/cstrom/local/node-v0.5.0-pre/lib/node_modules/vows/node_modules/eyes
vows@0.5.8 /home/cstrom/local/node-v0.5.0-pre/lib/node_modules/vows

➜ node-spdy git:(master) ✗ vows --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
When calling server.close
✓ all connections will be dropped

✓ OK » 8 honored (0.026s)
The vow for sending a request body when the client has sent a SYN_STREAM looks promising. I might ultimately write something similar, but include additional resources when specified requests are made. But for now, I spike.

But where to spike? Whilst digging around, I come across the following in lib/spdy/response.js:
/**
* Server push
*/
Response.prototype.createPushStream = function() {
// stub
};
Ah, that's the stuff. Just begging to be implemented.

For now, I start a new class named PushStream (Stream might have been more appropriate, but is already taken in node land):
/**
* PushStream class
*/

var Buffer = require('buffer').Buffer,
//... more modules requires...

/**
* Class constructor
*/
var PushStream = exports.PushStream = function(cframe, c) {
stream.Stream.call(this);
this.associatedStreamId = cframe.data.streamID;
this.c = c;

this._headers = {
};
this._written = false;

// For stream.pipe and others
this.writable = true;
};
util.inherits(PushStream, stream.Stream);
Unlike the response class, the push will not go out over the same stream. This will be a server initiated stream, but it does need to be associated with the original request (to pick up some headers and help the client identify the stream). Hence, the associated stream ID needs to be set in response to the original SYN_STREAM request.

I would have preferred to have gotten a bit further on this, but that will suffice as a stopping point for tonight. Now that I have a clear understanding of what needs to be done, I hope to make better progress on this tomorrow.


Day #31

Tuesday, May 24, 2011

XHR Over SPDY

‹prev | My Chain | next›

I continue today working through some unexpected behavior observed when looking at SPDY requests and SPDY responses in detail. With the SETTINGS frame more-or-less answered (Chrome is broke), I move onto two homepage requests for the node-spdy sample app:



When I first looked into it, I also noted a "bizarre" plain text server response immediately after a second home page request
request »»»
70 7.122965 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000 00 00 00 05 01 00 00 12 68 65 6c 6c 6f 20 66 72 ........ hello fr
0010 6f 6d 20 73 65 72 76 65 72 21 om serve r!
This is a non-compressed data frame from the client. It says "hello from server!" in the packet, which shows up on the displayed page, but this is definitely going from the client to the server (port 8081):



Before digging deeper, I check another conversation to find:



Another request from the client to the server, but... I find just a little later:



That really is odd. In this case the server really did respond with "hello from server!"

In the first sample conversation, there was one packet which, for some unknown reason, Wireshark was not able to decrypt. It would seem that the packet in question was the server responding with "hello from server!" That aside, I need to see what is going on here, so I ack through the node-spdy code for "hello from server" to find it is defined in pub/index.html:
      var xhr = new XMLHttpRequest();

xhr.open('POST', '/', true);
xhr.onreadystatechange = function() {
if (xhr.readyState === 4) {
document.getElementById('content').innerHTML = xhr.responseText;
}
};
xhr.send("hello from server!");
Nice. Old school XHR.

That snippet opens the root resource on the node-spdy test server for an asynchronous (the true param) POST. When the XHR request is complete, the response is put inside the element with ID of "content". Lastly, it sends the XHR off to the server. I would guess that the server simply echos POSTs back, but why guess?

From the node-spdy examples/spdy-server.js:
var server = spdy.createServer(options, function(req, res) {
if (req.method == 'POST') {
res.writeHead(200);
req.pipe(res);
return;
}

static(req, res, function() {
res.writeHead(404);
res.end();
});
});
Yup, for a POST, respond with a 200/OK and write the request back to the client.

Ooh! Nice pipe() in there. Rather than read the request payload and then explicitly writing it back out to the response stream, the example server pipes the request stream into the response stream.

Good stuff and another minor mystery solved. Up tomorrow I will either investigate server push or compressing html/js/css.


Day #30

Monday, May 23, 2011

What Endian the SETTINGS SPDY Frame?

‹prev | My Chain | next›

Today I begin my investigation of some things I did not quite understand while looking at SPDY requests and SPDY responses in detail. To get up to speed with the node-spdy codebase, I start with an easy one: the SETTINGS frame.

While examining the SPDY response SETTINGS frame last night, I noticed that it does not match up with the spec:
              +----------------------------------+
80 02 00 04 |1| version | 4 |
+----------------------------------+
00 00 00 0c | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 01 | Number of entries |
+----------------------------------+
04 00 00 00 | ID / |
00 00 00 64 | Value Pairs ... |
Specifically, the ID is wrong. The first octet ought to be an optional flag (0x1 = client should persist this setting; 0x2 = this is a persisted value). The actual value being set, 0x04 is not a valid SPDY SETTINGS frame flag, so I would guess that this is the ID. Per the SPDY draft (#2) spec, an ID of 0x04 is SETTINGS_MAX_CONCURRENT_STREAMS.

Looking through the node-spdy source, I see that a server is created with the following default options:
var Server = core.Server = function(options, requestListener) {
var that = this,
connectionSettings = options.connectionSettings || {
SETTINGS_MAX_CONCURRENT_STREAMS: 100
};
...
Those settings are sent back to the client at the end of the TLS server callback (i.e. for each TLS server connection):

...
// Send settings
c.write(createSettingsFrame(c.zlib, connectionSettings));
...
Checking out the createSettingsFrame method, I find:
/**
* Create SETTINGS frame
*/
exports.createSettingsFrame = function(zlib, settings) {
var keys = Object.keys(settings),
keysLen = keys.length,
buff = new Buffer(4 + 8 * keysLen);

// Insert keys count
buff.writeUInt32(keysLen, 0, 'big');

keys.reduce(function(offset, key) {
var raw_key = enums[key];

buff.writeUInt32(raw_key & 0xffffff, offset, 'little');

var value = settings[key];
buff.writeUInt32(value, offset + 4, 'big');

return offset + 8;
}, 4);

return createControlFrame(zlib, {
type: enums.SETTINGS
}, buff);
};
The zlib context being passed in is required to decompress/compress multiple frames over the course of a single connection. The settings are an object literal like that from the server core ({SETTINGS_MAX_CONCURRENT_STREAMS: 100}). The createSettingsFrame function then builds a buffer large enough to hold 4 bytes/octets describing the number of keys being set (one in this case) plus 8 bytes/octets for each key. The number of keys are written to the first four octets (via writeUInt32 / 32 bits). Next, the code iterates (using a reduce) over each key writing the ID in the first 32 bits and the value in the second 32 bits.

But why the use of little-endian byte order? All packets that I have seen so far have been in big-endian order—something the spec confirms:
All integer values, including length, version, and type, are in network byte order.
So I change the ID/Value pair code to read:
...
var raw_key = enums[key];

buff.writeUInt32(raw_key, offset, 'big');

var value = settings[key];
buff.writeUInt32(value, offset + 4, 'big');

return offset + 8;
...
Checking this out in the console, I find:
➜  node-spdy git:(master) ✗ node
> var createSettingsFrame = require('./lib/spdy').createSettingsFrame,
... createZLib = require('./lib/spdy').createZLib,
... enums = require('./lib/spdy').enums;
>
> createSettingsFrame(createZLib(), {SETTINGS_MAX_CONCURRENT_STREAMS: 100});
SETTINGS_MAX_CONCURRENT_STREAMS
<Buffer 80 02 00 04 00 00 00 0c 00 00 00 01 00 00 00 04 00 00 00 64>
Matching that up with the spec, I find:
                +----------------------------------+
80 02 00 04 |1| 1 | 4 |
+----------------------------------+
00 00 00 0c | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 01 | Number of entries |
+----------------------------------+
00 00 00 04 | ID/ |
00 00 00 64 | Value Pairs... |
Easy-peasy.

A quick sanity check in Wireshark reveals that the packet is coming through as I expect:
0000  80 02 00 04 00 00 00 0c  00 00 00 01 00 00 00 04   ........ ........
0010 00 00 00 64 ...d
Still...

I find it very odd that node-spdy is choosing to be so explicit about the endian-ness here. One more sanity check reveals why. Examining the SPDY packets in Chrome's about:net-internals panel, I find:
t=1306207841256 [st=  8]     SPDY_SESSION_RECV_SETTINGS  
--> settings = ["[0:100]"]
Bizarre. I would have expected 4:100, where 4 indicates that I am trying to set SETTINGS_MAX_CONCURRENT_STREAMS.

If I revert to the little-endian order, then reload, net-internals tells me:
(P) t=1306207452900 [st=  6]     SPDY_SESSION_RECV_SETTINGS  
--> settings = ["[4:100]"]
So I guess there was a reason for that after all. It just seems to be a reason that violates the spec.

A mystery for another day.


Day #29

Sunday, May 22, 2011

SPDY Responses in Detail

‹prev | My Chain | next›

Yesterday, I examined the details of SPDY requests (to a test node-spdy server). In all, there were 5 SYN_STREAM requests that went through for this page:



(web page, same web page again, CSS stylesheet, image, favicon)

Today, I examine the details of the response from the node-spdy server.

The first response packet is the server hello / certificate:
««« response
57 6.993692 127.0.0.1 127.0.0.1 TLSv1 Server Hello, Certificate, Server Hello Done
0000 00 00 00 00 00 00 00 00 00 00 00 00 08 00 45 00 ..............E.
0010 02 b4 e5 02 40 00 40 06 55 3f 7f 00 00 01 7f 00 ....@.@.U?......
0020 00 01 1f 91 b1 a2 72 b9 33 3f 72 7d 25 c3 80 18 ......r.3?r}%...
0030 01 09 00 a9 00 00 01 01 08 0a 01 52 d6 3e 01 52 ...........R.>.R
0040 d6 3e 16 03 01 00 40 02 00 00 3c 03 01 4d d7 2c .>....@...<..M.,
0050 98 c6 35 6a c5 85 29 8c c1 cf 3d c1 80 e1 8e 81 ..5j..)...=.....
0060 a5 59 4e e4 af d0 76 e0 a2 19 02 86 67 00 00 35 .YN...v.....g..5
0070 01 00 14 ff 01 00 01 00 00 23 00 00 33 74 00 07 .........#..3t..
0080 06 73 70 64 79 2f 32 16 03 01 02 2d 0b 00 02 29 .spdy/2....-...)
0090 00 02 26 00 02 23 30 82 02 1f 30 82 01 88 02 09 ..&..#0...0.....
00a0 00 8f 3d 25 00 6b c4 19 a2 30 0d 06 09 2a 86 48 ..=%.k...0...*.H
00b0 86 f7 0d 01 01 05 05 00 30 54 31 0b 30 09 06 03 ........0T1.0...
00c0 55 04 06 13 02 52 55 31 13 30 11 06 03 55 04 08 U....RU1.0...U..
00d0 13 0a 53 6f 6d 65 2d 53 74 61 74 65 31 0d 30 0b ..Some-State1.0.
00e0 06 03 55 04 07 13 04 4f 6d 73 6b 31 21 30 1f 06 ..U....Omsk1!0..
00f0 03 55 04 0a 13 18 49 6e 74 65 72 6e 65 74 20 57 .U....Internet W
0100 69 64 67 69 74 73 20 50 74 79 20 4c 74 64 30 1e idgits Pty Ltd0.
...
Most of that is just plain-old SSL. The only new / SPDY thing in there is the list of protocols supported. In this example server, only SPDY is supported (when accessing Google's servers, SPDY, HTTP/1.1 and HTTP/1.0 are supported).

The next response is:
««« response
60 7.000103 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000 14 00 00 0c 3d 6a eb 5a 0d 58 9e c0 03 5d a9 41 ....=j.Z.X...].A
==
0000 80 02 00 04 00 00 00 0c 00 00 00 01 04 00 00 00 ................
0010 00 00 00 64 ...d
I am not quite sure what that first frame was (just SSL setup), but the second frame is a SETTINGS frame. Arranging the packets next to the packet diagram from SPDY protocol (draft 2):
              +----------------------------------+
80 02 00 04 |1| version | 4 |
+----------------------------------+
00 00 00 0c | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 01 | Number of entries |
+----------------------------------+
04 00 00 00 | ID/Value Pairs |
00 00 00 64 | ... |
The first row matches up exactly with the spec. The second indicates that there are no flags and 12 additional octets after this row (0x0c == 12). The number of entries indicates that there is only a single setting being set. Skipping ahead, the numeric value being set is 100 (0x64), but what is the ID in the ID/Value pair? The ID is supposed to be one octet of flags and 3 octets describing the ID. The ID in there is empty (00 00 00). That seems like a bug, but I will investigate another day.

The next response packet(s) packet looks like:
««« response
62 7.038667 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP trafficContinuation or non-HTTP trafficContinuation or non-HTTP traffic
0000 80 02 00 02 00 00 00 a3 00 00 00 01 00 00 78 bb ........ ......x.
0010 df a2 51 b2 62 e0 64 e0 42 c4 10 03 57 76 6a 6a ..Q.b.d. B...Wvjj
0020 81 6e 62 4e 66 59 2a 03 1f 6a 90 33 30 9b 59 5a .nbNfY*. .j.30.YZ
0030 30 f0 a2 c4 2d 83 20 c4 1d 3a 0a 50 97 d8 1a 30 0...-. . .:.P...0
0040 f0 a2 04 2e 83 2c 30 c0 74 14 0c 4d 14 80 c1 a3 .....,0. t..M....
0050 00 cc 0b 86 0a 06 46 56 c6 66 56 40 11 77 df 10 ......FV .fV@.w..
0060 06 16 50 ac 30 08 2b 01 cd d6 35 04 e5 04 60 aa ..P.0.+. ..5...`.
0070 07 65 04 03 25 06 1e e4 c8 63 90 80 87 9f b5 02 .e..%... .c......
0080 cc bf a1 21 6e ba 40 27 a1 a4 77 06 d6 a4 ca 12 ...!n.@' ..w.....
0090 20 c5 06 f1 2a 03 1b 30 0b 2a f8 7b 33 b0 43 3d ...*..0 .*.{3.C=
00a0 cd c0 01 0b 0b 00 00 00 00 ff ff ........ ...
==
0000 00 00 00 01 00 00 02 ba 3c 21 44 4f 43 54 59 50 ........ <!DOCTYP
0010 45 20 68 74 6d 6c 3e 0a 3c 68 74 6d 6c 3e 0a 20 E html>. <html>.
0020 20 3c 68 65 61 64 3e 0a 20 20 20 20 3c 6c 69 6e <head>. <lin
0030 6b 20 72 65 6c 3d 69 63 6f 6e 20 74 79 70 65 3d k rel=ic on type=
0040 69 6d 61 67 65 2f 70 6e 67 20 68 72 65 66 3d 22 image/pn g href="
0050 66 61 76 69 63 6f 6e 2e 70 6e 67 22 20 2f 3e 0a favicon. png" />.
...
That second packet is a SPDY DATA frame, but with uncompressed data. It would certainly be nice if the web page were compressed—something else to investigate.

Unraveling the first packet next to its spec, I see that it is a SYN_REPLY:
               +----------------------------------+       
80 02 00 02 |1| 1 | 2 |
+----------------------------------+
00 00 00 a3 | Flags (8) | Length (24 bits) |
+----------------------------------+
00 00 00 01 |X| Stream-ID (31bits) |
+----------------------------------+
00 00 78 bb | Unused | |
+---------------- |
df a2 51 b2 | Name/value header block |
62 e0 64 e0 | ... |
42 c4 10 03
57 76 6a 6a
...
To see what the Name/value header block in that packet is, I drop down to the node.js REPL:
var context = new ZLibContext(flatDict);

var octets_1 = [
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, 0xc0, 0x74, 0x14, 0x0c, 0x4d, 0x14, 0x80, 0xc1, 0xa3,
0x00, 0xcc, 0x0b, 0x86, 0x0a, 0x06, 0x46, 0x56, 0xc6, 0x66, 0x56, 0x40, 0x11, 0x77, 0xdf, 0x10,
0x06, 0x16, 0x50, 0xac, 0x30, 0x08, 0x2b, 0x01, 0xcd, 0xd6, 0x35, 0x04, 0xe5, 0x04, 0x60, 0xaa,
0x07, 0x65, 0x04, 0x03, 0x25, 0x06, 0x1e, 0xe4, 0xc8, 0x63, 0x90, 0x80, 0x87, 0x9f, 0xb5, 0x02,
0xcc, 0xbf, 0xa1, 0x21, 0x6e, 0xba, 0x40, 0x27, 0xa1, 0xa4, 0x77, 0x06, 0xd6, 0xa4, 0xca, 0x12,
0x20, 0xc5, 0x06, 0xf1, 0x2a, 0x03, 0x1b, 0x30, 0x0b, 0x2a, 0xf8, 0x7b, 0x33, 0xb0, 0x43, 0x3d,
0xcd, 0xc0, 0x01, 0x0b, 0x0b, 0x00, 0x00, 0x00, 0x00, 0xff, 0xff
];

var d1 = new Buffer(octets_1);
var u1 = context.inflate(d1);
u1.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\u001dSat, 14 May 2011 02:36:14 GMT\u0000\u0004etag\u0000\u0013"698-1305340574000"\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'
Those are normal HTTP headers for the following DATA response.

The next response packet is another SYN_REPLY:
««« response
65 7.078185 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000 80 02 00 02 00 00 00 22 00 00 00 03 00 00 22 c5 ......."......".
0010 eb c6 26 e6 34 f3 3a d0 6c fc 5e 17 07 7b 3d b9 ..&.4.:.l.^..{=.
0020 b8 98 5a 3e 07 00 00 00 ff ff ..Z>......
Running that through node (and re-using the zlib context for this stream), I find that this SYN_REPLY is for the stylesheet:
var octets_2 = [
0x22, 0xc5,
0xeb, 0xc6, 0x26, 0xe6, 0x34, 0xf3, 0x3a, 0xd0, 0x6c, 0xfc, 0x5e, 0x17, 0x07, 0x7b, 0x3d, 0xb9,
0xb8, 0x98, 0x5a, 0x3e, 0x07, 0x00, 0x00, 0x00, 0xff, 0xff
];

var d2 = new Buffer(octets_2);
var u2 = context.inflate(d2);
u2.toString();
'\u0000\t\u0000\nconnection\u0000\nkeep-alive\u0000\u000econtent-length\u0000\u0003347\u0000\rcache-control\u0000\u0011public, max-age=0\u0000\rlast-modified\u0000\u001dSat, 14 May 2011 02:36:14 GMT\u0000\u0004etag\u0000\u0013"347-1305340574000"\u0000\fcontent-type\u0000\u0017text/css; charset=UTF-8\u0000\raccept-ranges\u0000\u0005bytes\u0000\u0006status\u0000\u0006200 OK\u0000\u0007version\u0000\bHTTP/1.1'
The response packet that immediately follows the CSS header is:
««« response
67 7.108609 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP trafficContinuation or non-HTTP traffic
0000 00 00 00 03 00 00 01 5b 62 6f 64 79 20 7b 0a 20 .......[body {.
0010 20 70 61 64 64 69 6e 67 3a 20 30 3b 0a 20 20 6d padding: 0;. m
0020 61 72 67 69 6e 3a 20 30 3b 0a 7d 0a 0a 73 65 63 argin: 0;.}..sec
0030 74 69 6f 6e 23 6d 61 69 6e 20 7b 0a 20 20 6d 61 tion#main {. ma
0040 72 67 69 6e 3a 20 30 20 61 75 74 6f 3b 0a 20 20 rgin: 0 auto;.
0050 6d 61 78 2d 77 69 64 74 68 3a 20 36 30 30 70 78 max-width: 600px
0060 3b 0a 20 20 74 65 78 74 2d 61 6c 69 67 6e 3a 20 ;. text-align:
0070 63 65 6e 74 65 72 3b 0a 20 20 62 61 63 6b 67 72 center;. backgr
0080 6f 75 6e 64 3a 20 75 72 6c 28 73 70 64 79 2e 6a ound: url(spdy.j
0090 70 67 29 20 6e 6f 2d 72 65 70 65 61 74 20 35 30 pg) no-repeat 50
00a0 25 20 35 30 25 3b 0a 20 20 68 65 69 67 68 74 3a % 50%;. height:
00b0 20 33 30 30 70 78 3b 0a 7d 0a 0a 73 65 63 74 69 300px;.}..secti
00c0 6f 6e 23 6d 61 69 6e 20 68 31 2e 74 69 74 6c 65 on#main h1.title
00d0 20 7b 0a 20 20 63 6f 6c 6f 72 3a 20 23 33 33 33 {. color: #333
00e0 3b 0a 7d 0a 0a 73 65 63 74 69 6f 6e 23 6d 61 69 ;.}..section#mai
00f0 6e 20 64 69 76 23 63 6f 6e 74 65 6e 74 20 7b 0a n div#content {.
0100 20 20 74 65 78 74 2d 73 68 61 64 6f 77 3a 20 30 text-shadow: 0
0110 20 30 20 35 70 78 20 72 67 62 61 28 30 2c 30 2c 0 5px rgba(0,0,
0120 30 2c 30 2e 33 29 3b 0a 20 20 66 6f 6e 74 2d 73 0,0.3);. font-s
0130 69 7a 65 3a 20 32 35 70 78 3b 0a 20 20 62 61 63 ize: 25px;. bac
0140 6b 67 72 6f 75 6e 64 3a 20 72 67 62 61 28 32 35 kground: rgba(25
0150 35 2c 32 35 35 2c 32 35 35 2c 30 2e 36 29 3b 0a 5,255,255,0.6);.
0160 7d 0a 0a }..
==
0000 00 00 00 03 01 00 00 00 ........
... which is another uncompressed DATA response frame.

The next response packet is a SYN_REPLY:
««« response
72 7.123613 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000 80 02 00 02 00 00 00 13 00 00 00 05 00 00 62 60 ..............b`
0010 c6 e9 73 c2 9a 01 00 00 00 ff ff ..s........
The NV frame decompresses to:
'\u0000\u0003\u0000\nconnection\u0000\nkeep-alive\u0000\u0006status\u0000\u0006200 OK\u0000\u0007version\u0000\bHTTP/1.1'
That seems intended for little more than simple keep-alive. Another something to investigate.

Next up, comes a small DATA response:
««« response
74 7.131888 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP trafficContinuation or non-HTTP traffic
0000 00 00 00 05 00 00 00 12 68 65 6c 6c 6f 20 66 72 ........hello fr
0010 6f 6d 20 73 65 72 76 65 72 21 om server!
==
0000 00 00 00 05 01 00 00 00 ........
This data ends up on the banner of the sample page.

I know that it is a DATA packet because it matches up with the spec:
              +----------------------------------+
00 00 00 05 |C| Stream-ID (31bits) |
+----------------------------------+
00 00 00 12 | Flags (8) | Length (24 bits) |
+----------------------------------+
68 65 6c 6c | Data |
6f 20 66 72 +----------------------------------+
6f 6d 20 73
65 72 76 65
72 21
Similarly, the DATA_FIN:
              +----------------------------------+
00 00 00 05 |C| Stream-ID (31bits) |
+----------------------------------+
01 00 00 00 | Flags (8) | Length (24 bits) |
+----------------------------------+
| Data |
+----------------------------------+
The DATA_FIN is indicated by the flag (0x01).

Next is another SYN_REPLY frame followed by the uncompressed JPEG background image:
««« response
75 7.139855 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP trafficContinuation or non-HTTP traffic
0000 80 02 00 02 00 00 00 26 00 00 00 07 00 00 22 21 .......&......"!
0010 d8 58 cd cd cc 0c 69 15 70 a2 4a 60 d3 f1 07 1d .X....i.p.J`....
0020 17 2c 8f a5 a6 93 1d 5a 00 00 00 00 ff ff .,.....Z......
==
0000 00 00 00 07 00 00 a0 00 ff d8 ff e0 00 10 4a 46 ..............JF
0010 49 46 00 01 01 00 00 01 00 01 00 00 ff fe 00 3c IF.............<
0020 43 52 45 41 54 4f 52 3a 20 67 64 2d 6a 70 65 67 CREATOR: gd-jpeg
0030 20 76 31 2e 30 20 28 75 73 69 6e 67 20 49 4a 47 v1.0 (using IJG
0040 20 4a 50 45 47 20 76 36 32 29 2c 20 71 75 61 6c JPEG v62), qual
0050 69 74 79 20 3d 20 31 30 30 0a ff db 00 43 00 01 ity = 100....C..
0060 01 01 01 01 01 01 01 01 01 01 01 01 01 01 01 01 ................
...
The NV section of the SYN_REPLY frame decompresses to the image header:
'\u0000\t\u0000\nconnection\u0000\nkeep-alive\u0000\u000econtent-length\u0000\u000576617\u0000\rcache-control\u0000\u0011public, max-age=0\u0000\rlast-modified\u0000\u001dSat, 14 May 2011 02:36:14 GMT\u0000\u0004etag\u0000\u0015"76617-1305340574000"\u0000\fcontent-type\u0000\nimage/jpeg\u0000\raccept-ranges\u0000\u0005bytes\u0000\u0006status\u0000\u0006200 OK\u0000\u0007version\u0000\bHTTP/1.1'
The next few packets are more of the JPEG image:
««« response
77 7.142581 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000 f9 9d f5 7e f5 e5 08 ef aa b2 ed 7e e8 fb ec f5 ...~.......~....
0010 f5 f5 ce 3a 71 c9 f9 78 ea 33 d8 01 eb 40 ef c1 ...:q..x.3...@..
0020 e9 8e 40 c9 c8 e3 3c 1f 7c 93 c1 23 8e 32 28 1f ..@...<.|..#.2(.
0030 9e 79 1c 91 9e 79 1c e7 3d 00 e4 0e 0f 6a 5f 51 .y...y..=....j_Q
0040 cf 6c e7 39 e9 d3 8e fd f2 38 39 c7 7c d4 1b 09 .l.9.....89.|...
0050 9f 63 c7 5e 3a 72 0f a7 3c e3 18 e7 b9 ec 69 79 .c.^:r..<.....iy
...

««« response
78 7.142701 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000 a9 5e 70 a3 4a 8c 5c e4 9a 4a 33 bd e0 af 81 d7 .^p.J.\..J3.....
0010 fa ae 81 69 e3 9f 1e 78 83 4b f8 4d f0 ce e1 9a ...i...x.K.M....
0020 3d 2b c4 de 22 b6 9a e3 57 f1 57 d9 fe 5b 8b 3f =+.."...W.W..[.?
0030 87 1e 08 b2 0b ad f8 ca 58 06 d4 92 fe ca 1b 4f ........X......O
0040 0c 69 f8 51 a8 6b 76 63 6a 57 b2 f8 64 78 2b 4f .i.Q.kvcjW..dx+O
0050 06 3f 82 9f 05 ed 7c 4b 35 bb 98 5b e2 87 c7 3f .?....|K5..[...?
...

««« response
79 7.147850 127.0.0.1 127.0.0.1 TLSv1 Application Data
???

««« response
81 7.150942 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP trafficContinuation or non-HTTP traffic
0000 00 00 00 07 00 00 8b 49 8f 7d 3a 73 86 9e 5d 3f .......I.}:s..]?
0010 44 32 49 8c e7 26 e2 ea ed c9 3c 96 91 fd 71 5f D2I..&....<...q_
0020 e9 3f 83 19 54 72 cf 0f b8 17 0b 18 a5 53 34 cd .?..Tr.......S4.
0030 69 e6 55 93 8a 8d e1 42 15 31 15 17 2b b3 49 62 i.U....B.1..+.Ib
0040 68 ae 64 d5 e5 2a 92 9a 56 97 31 fc 37 e2 6e 62 h.d..*..V.1.7.nb
0050 f1 dc 67 c5 b5 dc a4 fe a1 97 bc 0d 3b b7 3a 6a ..g.........;.:j
...

««« response
83 7.154903 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000 c8 60 11 a3 d5 f4 bd 46 67 8f 04 82 16 e1 25 61 .`.....Fg.....%a
0010 c1 9b 19 af be 79 c1 f7 c9 38 e7 af 00 f4 e9 e8 .....y...8......
0020 07 38 f5 20 d0 54 f6 c6 38 c0 e3 f1 27 8f 4f af .8. .T..8...'.O.
0030 f4 af 57 0d 9e e7 58 3b 2c 36 6b 8e a4 96 d0 8e ..W...X;,6k.....
0040 22 a3 a6 b6 fb 0e 4d 5b 4f f3 b9 e6 57 c9 72 ac ".....M[O...W.r.
0050 4b 6e b6 5f 84 9b 77 6e 4e 8c 14 af bd ef 14 9b Kn._..wnN.......
...

««« response
85 7.188625 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000 00 00 00 07 01 00 00 00 ........
The last packet is a DATA_FIN. Also included in there is a non-decrypted packet. I am unsure about that one. It originates from the example node-spdy server (the SRC port is 8081), but I am hard pressed to explain why Wireshark is unable to decrypt it. Another mystery.

The last packets are the header for the favicon:
««« response
88 7.295411 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000 80 02 00 02 00 00 00 23 00 00 00 09 00 00 22 c1 .......#......".
0010 c3 2c 46 a6 16 46 34 f2 af 88 12 c8 70 fc de e5 .,F..F4.....p...
0020 84 97 2d 64 fb 16 00 00 00 ff ff ..-d.......
This decompresses to:
'\u0000\t\u0000\nconnection\u0000\nkeep-alive\u0000\u000econtent-length\u0000\u00042582\u0000\rcache-control\u0000\u0011public, max-age=0\u0000\rlast-modified\u0000\u001dSat, 14 May 2011 02:36:14 GMT\u0000\u0004etag\u0000\u0014"2582-1305340574000"\u0000\fcontent-type\u0000\timage/png\u0000\raccept-ranges\u0000\u0005bytes\u0000\u0006status\u0000\u0006200 OK\u0000\u0007version\u0000\bHTTP/1.1'
Lastly, the favicon PNG itself is sent back:
««« response
90 7.296229 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000 00 00 00 09 00 00 0a 16 89 50 4e 47 0d 0a 1a 0a .........PNG....
0010 00 00 00 0d 49 48 44 52 00 00 00 20 00 00 00 20 ....IHDR... ...
0020 08 06 00 00 00 73 7a 7a f4 00 00 09 dd 49 44 41 .....szz.....IDA
0030 54 58 85 c5 97 69 6c 5c d7 79 86 9f bb cc 90 33 TX...il\.y.....3
0040 1c 0e 17 91 22 29 c9 9c 11 29 4a a2 2c ca 92 2c ....")...)J.,..,
0050 59 b6 6c c9 72 e4 38 71 ea b8 46 63 48 ad 52 a3 Y.l.r.8q..FcH.R.
...

««« response
92 7.296729 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000 00 00 00 09 01 00 00 00 ........
...ending with a DATA_FIN again.

And that completes the request/response. I believe that the SETTING frame is in error. I am unsure if the stream needs to be closed after each response as it is. Also, I would like to investigate compressed the DATA some. Aside from a few loose end, this is a fine stopping place for the day.


Day #28