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.jsWhat. The.
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)
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:...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
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
t=1306724141128 [st=46] SPDY_SESSION_SYN_REPLYThat is just normal HTTP over SPDY. The stream ID (1) is picked up from what Chrome sent in the original request.
--> 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
Next up is the push stream initialization and data:
t=1306724141128 [st=46] SPDY_SESSION_PUSHED_SYN_STREAMThis 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.
--> 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
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_DATALast to come through is:
--> 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_STREAMI 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 8081After 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):
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
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:
+----------------------------------+Next is the push stream, identified by the stream ID (2) and the presence of an associated stream ID (1):
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
+----------------------------------+So far, so good.
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
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 ........<!DOCTYPAgain, 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.
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" />.
...
The last frame sent from the server is a DATA FIN:
+----------------------------------+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.
00 00 00 01 |C| Stream-ID (31bits) |
+----------------------------------+
01 00 00 00 | Flags (8) | Length (24 bits) |
+----------------------------------+
| Data |
+----------------------------------+
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
No comments:
Post a Comment