SPDY Requests in Detail

‹prev | My Chain | next›

Today, I am going to examine a SPDY session in excruciating detail. Specifically, I am going to go through the request packets for the following page (from the node-spdy example server):



The entire conversation from Wireshark looks like:

request »»»
55 6.993317 127.0.0.1 127.0.0.1 TLSv1 Client Hello

««« response
57 6.993692 127.0.0.1 127.0.0.1 TLSv1 Server Hello, Certificate, Server Hello Done

request »»»
59 6.995636 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« response
60 7.000103 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« 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

request »»»
64 7.074843 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« response
65 7.078185 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« response
67 7.108609 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP trafficContinuation or non-HTTP traffic

request »»»
69 7.120765 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

request »»»
70 7.122965 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« response
72 7.123613 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

request »»»
73 7.131861 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« response
74 7.131888 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP trafficContinuation or non-HTTP traffic

««« response
75 7.139855 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP trafficContinuation or non-HTTP traffic

««« response
77 7.142581 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« response
78 7.142701 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« 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

««« response
83 7.154903 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« response
85 7.188625 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

request »»»
87 7.293050 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« response
88 7.295411 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« response
90 7.296229 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

««« response
92 7.296729 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic

There are seven requests in all. The first is:

request »»»
55 6.993317 127.0.0.1 127.0.0.1 TLSv1 Client Hello
0000   00 00 00 00 00 00 00 00 00 00 00 00 08 00 45 00  ..............E.
0010   00 e9 f3 35 40 00 40 06 48 d7 7f 00 00 01 7f 00  ...5@.@.H.......
0020   00 01 b1 a2 1f 91 72 7d 25 0e 72 b9 33 3f 80 18  ......r}%.r.3?..
0030   01 01 fe dd 00 00 01 01 08 0a 01 52 d6 3e 01 52  ...........R.>.R
0040   d6 3e 16 03 01 00 b0 01 00 00 ac 03 01 4d d7 2c  .>...........M.,
0050   98 2f 60 55 4a 0c 0e ef c4 ad 10 b6 42 82 d9 53  ./`UJ.......B..S
0060   84 34 e2 2f 4a 79 11 4e 27 a7 2e eb 71 00 00 48  .4./Jy.N'...q..H
0070   c0 0a c0 14 00 88 00 87 00 39 00 38 c0 0f c0 05  .........9.8....
0080   00 84 00 35 c0 07 c0 09 c0 11 c0 13 00 45 00 44  ...5.........E.D
0090   00 66 00 33 00 32 c0 0c c0 0e c0 02 c0 04 00 96  .f.3.2..........
00a0   00 41 00 04 00 05 00 2f c0 08 c0 12 00 16 00 13  .A...../........
00b0   c0 0d c0 03 fe ff 00 0a 02 01 00 00 3a 00 00 00  ............:...
00c0   0e 00 0c 00 00 09 6c 6f 63 61 6c 68 6f 73 74 ff  ......localhost.
00d0   01 00 01 00 00 0a 00 08 00 06 00 17 00 18 00 19  ................
00e0   00 0b 00 02 01 00 00 23 00 00 33 74 00 00 00 05  .......#..3t....
00f0   00 05 01 00 00 00 00                             .......

That is just a normal SSL request. Nothing SPDY-like in there. The second request:

request »»»
59 6.995636 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000  43 00 00 20 06 73 70 64  79 2f 32 18 00 00 00 00   C.. .spd y/2.....
0010  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00   ........ ........
0020  00 00 00 00 14 00 00 0c  50 e0 b6 d9 32 f5 aa eb   ........ P...2...
0030  2d 4d 31 68                                        -M1h
==
0000  80 02 00 01 01 00 01 41  00 00 00 01 00 00 00 00   .......A ........
0010  00 00 38 ea df a2 51 b2  62 e0 65 60 83 a4 17 06   ..8...Q. b.e`....
0020  7b b8 0b 75 30 2c d6 ae  40 17 cd cd b1 2e b4 35   {..u0,.. @......5
0030  d0 b3 d4 d1 d2 d7 02 b3  2c 18 f8 50 73 2c 83 9c   ........ ,..Ps,..
0040  67 b0 3f d4 3d 3a 60 07  81 d5 99 eb 40 d4 1b 33   g.?.=:`. ....@..3
0050  f0 a3 e5 69 06 41 90 8b  75 a0 4e d6 29 4e 49 ce   ...i.A.. u.N.)NI.
0060  80 ab 81 25 03 06 be d4  3c dd d0 60 9d d4 3c a8   ...%.... <..`..<.
0070  a5 bc 28 89 8d 81 23 2f  5f 17 2c c2 c0 06 89 53   ..(...#/ _.,....S
0080  06 19 60 89 92 ad 57 9c  5a 0c f2 b2 ad 93 63 86   ..`...W. Z.....c.
0090  b9 a3 a3 aa b1 0b 08 19  38 32 b0 80 8a 08 06 3e   ........ 82.....>
00a0  50 3a ca 01 31 ad 2c 0c  2c 0c 19 d8 72 81 45 53   P:..1.,. ,...r.ES
00b0  7e 0a 03 b3 bb 6b 08 03  40 6c 05 45 89 e9 b9 89   ~....k.. @l.E....
00c0  c8 46 17 03 c9 dc 54 06  d6 8c 92 92 82 62 06 66   .F....T. .....b.f
00d0  50 40 32 ea 33 70 21 72  3f 43 9a 6f 7e 55 66 4e   P@2.3p!r ?C.o~UfN
00e0  4e a2 be a9 9e 81 82 46  84 a1 a1 b5 82 4f 66 5e   N......F .....Of^
00f0  69 85 42 85 85 59 bc 99  89 a6 82 23 30 30 53 c3   i.B..Y.. ...#00S.
0100  53 93 bc 33 4b f4 4d 8d  4d f4 8c cd 14 34 bc 3d   S..3K.M. M....4.=
0110  42 7c 7d 74 14 72 32 b3  53 15 dc 53 93 b3 f3 35   B|}t.r2. S..S...5
0120  15 9c 33 80 c5 58 aa be  a1 b1 1e 30 e4 cc cc f5   ..3..X.. ...0....
0130  0c 15 82 13 d3 12 8b 32  a1 7a 18 d8 a1 71 c9 c0   .......2 .z...q..
0140  01 8b 62 00 00 00 00 ff  ff                        ..b..... .

There are two compressed frames in there (note-to-self: are these two different packets assembled into one by Wireshark?). The first packet is confirmation to the server of a SPDY session. The second packet is a SYN_STREAM frame (fourth octet is 0x01). The first line of that packet is SYN_STREAM overhead: control bit, SPDY version, the SYN_STREAM type, the packet length, etc. The rest of the packet is name-value (NV) data. I know how to decompress NV data!

I drop into the node REPL to see the decompressed contents of the NV frame (with setup from the other day):

> var context = new ZLibContext(flatDict);
> var d1 = new Buffer([0x38, 0xea, 0xdf, 0xa2, 0x51, 0xb2, 0x62, 0xe0, 0x65, 0x60, 0x83, 0xa4, 0x17, 0x06, 0x7b, 0xb8, 0x0b, 0x75, 0x30, 0x2c, 0xd6, 0xae, 0x40, 0x17, 0xcd, 0xcd, 0xb1, 0x2e, 0xb4, 0x35, 0xd0, 0xb3, 0xd4, 0xd1, 0xd2, 0xd7, 0x02, 0xb3, 0x2c, 0x18, 0xf8, 0x50, 0x73, 0x2c, 0x83, 0x9c, 0x67, 0xb0, 0x3f, 0xd4, 0x3d, 0x3a, 0x60, 0x07, 0x81, 0xd5, 0x99, 0xeb, 0x40, 0xd4, 0x1b, 0x33, 0xf0, 0xa3, 0xe5, 0x69, 0x06, 0x41, 0x90, 0x8b, 0x75, 0xa0, 0x4e, 0xd6, 0x29, 0x4e, 0x49, 0xce, 0x80, 0xab, 0x81, 0x25, 0x03, 0x06, 0xbe, 0xd4, 0x3c, 0xdd, 0xd0, 0x60, 0x9d, 0xd4, 0x3c, 0xa8, 0xa5, 0xbc, 0x28, 0x89, 0x8d, 0x81, 0x23, 0x2f, 0x5f, 0x17, 0x2c, 0xc2, 0xc0, 0x06, 0x89, 0x53, 0x06, 0x19, 0x60, 0x89, 0x92, 0xad, 0x57, 0x9c, 0x5a, 0x0c, 0xf2, 0xb2, 0xad, 0x93, 0x63, 0x86, 0xb9, 0xa3, 0xa3, 0xaa, 0xb1, 0x0b, 0x08, 0x19, 0x38, 0x32, 0xb0, 0x80, 0x8a, 0x08, 0x06, 0x3e, 0x50, 0x3a, 0xca, 0x01, 0x31, 0xad, 0x2c, 0x0c, 0x2c, 0x0c, 0x19, 0xd8, 0x72, 0x81, 0x45, 0x53, 0x7e, 0x0a, 0x03, 0xb3, 0xbb, 0x6b, 0x08, 0x03, 0x40, 0x6c, 0x05, 0x45, 0x89, 0xe9, 0xb9, 0x89, 0xc8, 0x46, 0x17, 0x03, 0xc9, 0xdc, 0x54, 0x06, 0xd6, 0x8c, 0x92, 0x92, 0x82, 0x62, 0x06, 0x66, 0x50, 0x40, 0x32, 0xea, 0x33, 0x70, 0x21, 0x72, 0x3f, 0x43, 0x9a, 0x6f, 0x7e, 0x55, 0x66, 0x4e, 0x4e, 0xa2, 0xbe, 0xa9, 0x9e, 0x81, 0x82, 0x46, 0x84, 0xa1, 0xa1, 0xb5, 0x82, 0x4f, 0x66, 0x5e, 0x69, 0x85, 0x42, 0x85, 0x85, 0x59, 0xbc, 0x99, 0x89, 0xa6, 0x82, 0x23, 0x30, 0x30, 0x53, 0xc3, 0x53, 0x93, 0xbc, 0x33, 0x4b, 0xf4, 0x4d, 0x8d, 0x4d, 0xf4, 0x8c, 0xcd, 0x14, 0x34, 0xbc, 0x3d, 0x42, 0x7c, 0x7d, 0x74, 0x14, 0x72, 0x32, 0xb3, 0x53, 0x15, 0xdc, 0x53, 0x93, 0xb3, 0xf3, 0x35, 0x15, 0x9c, 0x33, 0x80, 0xc5, 0x58, 0xaa, 0xbe, 0xa1, 0xb1, 0x1e, 0x30, 0xe4, 0xcc, 0xcc, 0xf5, 0x0c, 0x15, 0x82, 0x13, 0xd3, 0x12, 0x8b, 0x32, 0xa1, 0x7a, 0x18, 0xd8, 0xa1, 0x71, 0xc9, 0xc0, 0x01, 0x8b, 0x62, 0x00, 0x00, 0x00, 0x00, 0xff, 0xff]);
> var u1 = context.inflate(d1);
> u1.toString();
'\u0000\r\u0000\u0006accept\u0000?text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\u0000\u000eaccept-charset\u0000\u001eISO-8859-1,utf-8;q=0.7,*;q=0.3\u0000\u000faccept-encoding\u0000\u0011gzip,deflate,sdch\u0000\u000faccept-language\u0000\u000een-US,en;q=0.8\u0000\rcache-control\u0000\bno-cache\u0000\u0006cookie\u0000\u001crack.session=BAh7AA%3D%3D%0A\u0000\u0004host\u0000\u000elocalhost:8081\u0000\u0006method\u0000\u0003GET\u0000\u0006pragma\u0000\bno-cache\u0000\u0006scheme\u0000\u0005https\u0000\u0003url\u0000\u0001/\u0000\nuser-agent\u0000fMozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.36 (KHTML, like Gecko) Chrome/13.0.767.1 Safari/534.36\u0000\u0007version\u0000\bHTTP/1.1'

Not surprisingly, that is a request for the homepage.

The next packet is:

request »»»
64 7.074843 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000  80 02 00 01 01 00 00 40  00 00 00 03 00 00 00 00   .......@ ........
0010  40 00 62 e0 83 c7 a8 10  38 46 93 8b 8b e1 91 64   @.b..... 8F.....d
0020  38 72 22 89 1d 5a 28 33  88 83 63 c9 4a 5f 1f 55   8r"..Z(3 ..c.J_.U
0030  bf 3e d6 68 e4 d2 2f 2e  a9 cc 49 d5 03 06 da 20   .>.h../. ..I....
0040  89 4f 00 00 00 00 ff ff                            .O......

Running that through the node REPL decompressor (re-using the same context, of course), I find:

 > var d2 = new Buffer([0x62, 0xe0, 0x83, 0xc7, 0xa8, 0x10, 0x38, 0x46, 0x93, 0x8b, 0x8b, 0xe1, 0x91, 0x64, 0x38, 0x72, 0x22, 0x89, 0x1d, 0x5a, 0x28, 0x33, 0x88, 0x83, 0x63, 0xc9, 0x4a, 0x5f, 0x1f, 0x55, 0xbf, 0x3e, 0xd6, 0x68, 0xe4, 0xd2, 0x2f, 0x2e, 0xa9, 0xcc, 0x49, 0xd5, 0x03, 0x06, 0xda, 0x20, 0x89, 0x4f, 0x00, 0x00, 0x00, 0x00, 0xff, 0xff]);
> var u2 = context.inflate(d2);
> u2.toString();
'\u0000\u000e\u0000\u0006accept\u0000\u0012text/css,*/*;q=0.1\u0000\u000eaccept-charset\u0000\u001eISO-8859-1,utf-8;q=0.7,*;q=0.3\u0000\u000faccept-encoding\u0000\u0011gzip,deflate,sdch\u0000\u000faccept-language\u0000\u000een-US,en;q=0.8\u0000\rcache-control\u0000\bno-cache\u0000\u0006cookie\u0000\u001crack.session=BAh7AA%3D%3D%0A\u0000\u0004host\u0000\u000elocalhost:8081\u0000\u0006method\u0000\u0003GET\u0000\u0006pragma\u0000\bno-cache\u0000\u0007referer\u0000\u0017https://localhost:8081/\u0000\u0006scheme\u0000\u0005https\u0000\u0003url\u0000\n/style.css\u0000\nuser-agent\u0000fMozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.36 (KHTML, like Gecko) Chrome/13.0.767.1 Safari/534.36\u0000\u0007version\u0000\bHTTP/1.1'

That is a request for the style.css file.

Next up is:

request »»»
69 7.120765 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000  80 02 00 01 00 00 00 46  00 00 00 05 00 00 00 00   .......F ........
0010  80 00 62 10 84 c7 27 33  30 1a 07 59 04 f2 a1 96   ..b...'3 0..Y....
0020  cb 0c 4c 86 16 0c 3c c8  a5 2e d0 6c d4 62 83 2a   ..L...<. ...l.b.*
0030  71 ce 12 e0 1f 0c 8c f4  fc a2 cc f4 cc 3c 06 31   q....... .....<.1
0040  ec 31 4c b5 44 31 68 f2  36 00 00 00 ff ff         .1L.D1h. 6.....

This decompresses to:

'\u0000\u0011\u0000\u0006accept\u0000\u0003*/*\u0000\u000eaccept-charset\u0000\u001eISO-8859-1,utf-8;q=0.7,*;q=0.3\u0000\u000faccept-encoding\u0000\u0011gzip,deflate,sdch\u0000\u000faccept-language\u0000\u000een-US,en;q=0.8\u0000\rcache-control\u0000\bno-cache\u0000\u000econtent-length\u0000\u000218\u0000\fcontent-type\u0000\u000fapplication/xml\u0000\u0006cookie\u0000\u001crack.session=BAh7AA%3D%3D%0A\u0000\u0004host\u0000\u000elocalhost:8081\u0000\u0006method\u0000\u0004POST\u0000\u0006origin\u0000\u0016https://localhost:8081\u0000\u0006pragma\u0000\bno-cache\u0000\u0007referer\u0000\u0017https://localhost:8081/\u0000\u0006scheme\u0000\u0005https\u0000\u0003url\u0000\u0001/\u0000\nuser-agent\u0000fMozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.36 (KHTML, like Gecko) Chrome/13.0.767.1 Safari/534.36\u0000\u0007version\u0000\bHTTP/1.1'

Weird that looks to be a second request for the top-level home page.

The next request packet is similar strange:

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!

Bizarre! That is just a plain-text, not-even-SPDY response. That certainly warrants some investigation at some point.

Next up, we return to SPDY request land:

request »»»
73 7.131861 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000  80 02 00 01 01 00 00 26  00 00 00 07 00 00 00 00   .......& ........
0010  80 00 42 ca db 83 30 2d  0c ba cc cc a9 5f 5c 90   ..B...0- ....._\.
0020  52 a9 97 55 90 3e 48 e2  0f 00 00 00 ff ff         R..U.>H. ......

This decompresses to:

'\u0000\u000e\u0000\u0006accept\u0000\u0003*/*\u0000\u000eaccept-charset\u0000\u001eISO-8859-1,utf-8;q=0.7,*;q=0.3\u0000\u000faccept-encoding\u0000\u0011gzip,deflate,sdch\u0000\u000faccept-language\u0000\u000een-US,en;q=0.8\u0000\rcache-control\u0000\bno-cache\u0000\u0006cookie\u0000\u001crack.session=BAh7AA%3D%3D%0A\u0000\u0004host\u0000\u000elocalhost:8081\u0000\u0006method\u0000\u0003GET\u0000\u0006pragma\u0000\bno-cache\u0000\u0007referer\u0000\u0017https://localhost:8081/\u0000\u0006scheme\u0000\u0005https\u0000\u0003url\u0000\t/spdy.jpg\u0000\nuser-agent\u0000fMozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.36 (KHTML, like Gecko) Chrome/13.0.767.1 Safari/534.36\u0000\u0007version\u0000\bHTTP/1.1'

This is a request for a JPEG image.

The last request is:

request »»»
87 7.293050 127.0.0.1 127.0.0.1 HTTP Continuation or non-HTTP traffic
0000  80 02 00 01 01 00 00 29  00 00 00 09 00 00 00 00   .......) ........
0010  80 00 62 e0 1e 04 f1 47  bd 68 c2 12 e4 3c fa 69   ..b....G .h...<.i
0020  89 65 99 c0 b4 a1 57 90  37 58 42 1d 00 00 00 ff   .e....W. 7XB.....
0030  ff                                                 .

Which decompresses to:

'\u0000\u000b\u0000\u0006accept\u0000\u0003*/*\u0000\u000eaccept-charset\u0000\u001eISO-8859-1,utf-8;q=0.7,*;q=0.3\u0000\u000faccept-encoding\u0000\u0011gzip,deflate,sdch\u0000\u000faccept-language\u0000\u000een-US,en;q=0.8\u0000\u0006cookie\u0000\u001crack.session=BAh7AA%3D%3D%0A\u0000\u0004host\u0000\u000elocalhost:8081\u0000\u0006method\u0000\u0003GET\u0000\u0006scheme\u0000\u0005https\u0000\u0003url\u0000\f/favicon.png\u0000\nuser-agent\u0000fMozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.36 (KHTML, like Gecko) Chrome/13.0.767.1 Safari/534.36\u0000\u0007version\u0000\bHTTP/1.1'

A favicon. Of course there had to be a favicon in there somewhere.

That about does it for tracing through the SPDY request side of things. There were a couple of unexpected things in there, but for the most part, normal HTTP requests over SPDY. I will investigate the unexpected another day. Tomorrow I will have a look-see at the response side.


Day #26

Moving On… to Node SPDY

‹prev | My Chain | next›

With zlib decompression of multiple SPDY packets working in both Python and Node.js, I am ready to punt on Ruby support. But first some specs enticing others to solve this for me.

I add the compressed and uncompressed values to the spec helper in the SPDY gem:

COMPRESSED_HEADER_1 = "8\xEA\xDF\xA2Q\xB2b\xE0b`\x83\xA4\x17\x06{\xB8\vu0,\xD6\xAE@\x17\xCD\xCD\xB1.\xB45\xD0\xB3\xD4\xD1\xD2\xD7\x02\xB3,\x18\xF8Ps,\x83\x9Cg\xB0?\xD4=:`\a\x81\xD5\x99\xEB@\xD4\e3\xF0\xA3\xE5i\x06A\x90\x8Bu\xA0N\xD6)NI\xCE\x80\xAB\x81%\x03\x06\xBE\xD4<\xDD\xD0`\x9D\xD4<\xA8\xA5,\xA0<\xCE\xC0\x0FJ\b9 \xA6\x150\xE3\x19\x180\xB0\xE5\x02\v\x97\xFC\x14\x06fw\xD7\x10\x06\xB6b`z\xCCMe`\xCD())(f`\x06y\x9CQ\x9F\x81\v\x91[\x19\xD2}\xF3\xAB2sr\x12\xF5M\xF5\f\x144\x00\x8A04\xB4V\xF0\xC9\xCC+\xADP\xA8\xB00\x8B73\xD1Tp\x04z>5<5\xC9;\xB3D\xDF\xD4\xD8D\xCF\x18\xA8\xCC\xDB#\xC4\xD7GG!'3;U\xC1=59;_S\xC19\x03X\xEC\xA4\xEA\e\x1A\xE9\x01}jb\x04R\x16\x9C\x98\x96X\x94\t\xD5\xC4\xC0\x0E\r|\x06\x0EX\x9C\x00\x00\x00\x00\xFF\xFF"

COMPRESSED_HEADER_2 = "B\x8A\x02f``\x0E\xAD`\xE4\xD1OK,\xCB\x04f3= 1XB\x14\x00\x00\x00\xFF\xFF"

UNCOMPRESSED_HEADER_1 = "\x00\n\x00\x06accept\x00?text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\x00\x0eaccept-charset\x00\x1eISO-8859-1,utf-8;q=0.7,*;q=0.3\x00\x0faccept-encoding\x00\x11gzip,deflate,sdch\x00\x0faccept-language\x00\x0een-US,en;q=0.8\x00\x04host\x00\x0flocalhost:10000\x00\x06method\x00\x03GET\x00\x06scheme\x00\x05https\x00\x03url\x00\x01/\x00\nuser-agent\x00gMozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.30 (KHTML, like Gecko) Chrome/12.0.742.30 Safari/534.30\x00\x07version\x00\x08HTTP/1.1"

UNCOMPRESSED_HEADER_2 = "\x00\n\x00\x06accept\x00\x03*/*\x00\x0eaccept-charset\x00\x1eISO-8859-1,utf-8;q=0.7,*;q=0.3\x00\x0faccept-encoding\x00\x11gzip,deflate,sdch\x00\x0faccept-language\x00\x0een-US,en;q=0.8\x00\x04host\x00\x0flocalhost:10000\x00\x06method\x00\x03GET\x00\x06scheme\x00\x05https\x00\x03url\x00\x0c/favicon.ico\x00\nuser-agent\x00gMozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.30 (KHTML, like Gecko) Chrome/12.0.742.30 Safari/534.30\x00\x07version\x00\x08HTTP/1.1"

I can then write a simple spec detailing my woes:

  it "can deflate multiple packets" do
    # see also https://gist.github.com/982287
    SPDY::Zlib.inflate(COMPRESSED_HEADER_1)

    SPDY::Zlib.inflate(COMPRESSED_HEADER_2).
      should == UNCOMPRESSED_HEADER_2
  end

Running that spec results in my nemesis, the "invalid stream" exception:

➜  spdy git:(master) ✗ rspec ./spec/compressor_spec.rb
..F

Failures:

  1) SPDY::Zlib can deflate multiple packets
     Failure/Error: SPDY::Zlib.inflate(COMPRESSED_HEADER_2).
     RuntimeError:
       invalid stream  
     # ./lib/spdy/compressor.rb:35:in `inflate'
     # ./spec/compressor_spec.rb:18:in `block (2 levels) in <top (required)>'

Finished in 0.00194 seconds
3 examples, 1 failure  

I mark that pending, commit to SPDY gem and open an issue. Someone please help!

I will continue to investigate this in my spare time, but, for now I turn back to node-spdy. Digging through edge-node.js some, I find the following SSL cipher suite being employed:

    creds.context.setCiphers('RC4-SHA:AES128-SHA:AES256-SHA');

Hrm... that does not seem to imclude my beloved DES-CBC3-SHA. Any chance Wireshark is able to decrypt (if supplied with the server keys) those cipher suites?

Ain't but one way to find out. I fire up the node-spdy example server:

➜  node-spdy git:(master) ✗ node test/spdy-server.js
TLS NPN Server is running on port : 8081

Then I need to start Wireshark, adding the example server's private key to the list of keys known to Wireshark:

127.0.0.1,10443,http,/home/cstrom/key.pem;127.0.0.1,10000,http,/home/cstrom/key.pem;127.0.0.1,8081,http,/home/cstrom/repos/node-spdy/keys/spdy-key.pem

With that I can start capture for packets on the loopback interface for port 8081. After making a request in Chrome, I see in Wireshark:



That is a whole lotta green. As is usual, green is good. In this case, the green packets indicate packets that have been decrypted. Nice!

But why so much green? Well, it turns out you need to send lots of data when rendering an awesome page:



For good measure, I inspect the first packet sent:



The destination port is 8081, so this is from the client to the server. The packet itself starts with 80 02 00 01 octets. The first octet (80) is just the control bit at the beginning of the control frame. The next (02) indicates the SPDY version being used here: 2. Lastly the remaining octets indicate the type of control frame being used: a SYN_STREAM which starts the SPDY session.

(More info can be found in the control frames section of the SPDY draft specification)

It is nice to have so much data at my disposal. I will pick back up tomorrow running through the various packets watching the nitty gritty SPDY packets in detail. Should be fun :)

Day #27

It Even Works in Python

‹prev | My Chain | next›

I have effectively dead-ended attempting to get Ruby to decompress multiple SPDY / ZLib packets. It works fine in node.js, but I cannot translate that knowledge into workable Ruby code. So today, I will try working through python code.

First up, I verify that it still works (it is somewhat old code). I copy the data from my node-spdy work into a python REPL and use the decompressor from the example code:

>>> d = Decompressor("optionsgetheadpostputdeletetraceacceptaccept-charsetaccept-encodingaccept-languageauthorizationexpectfromhostif-modified-sinceif-matchif-none-matchif-rangeif-unmodifiedsincemax-forwardsproxy-authorizationrangerefererteuser-agent100101200201202203204205206300301302303304305306307400401402403404405406407408409410411412413414415416417500501502503504505accept-rangesageetaglocationproxy-authenticatepublicretry-afterservervarywarningwww-authenticateallowcontent-basecontent-encodingcache-controlconnectiondatetrailertransfer-encodingupgradeviawarningcontent-languagecontent-lengthcontent-locationcontent-md5content-rangecontent-typeetagexpireslast-modifiedset-cookieMondayTuesdayWednesdayThursdayFridaySaturdaySundayJanFebMarAprMayJunJulAugSepOctNovDecchunkedtext/htmlimage/pngimage/jpgimage/gifapplication/xmlapplication/xhtmltext/plainpublicmax-agecharset=iso-8859-1utf-8gzipdeflateHTTP/1.1statusversionurl\x00")
>>> d1 = [0x38,0xea,0xdf,0xa2,0x51,0xb2,0x62,0xe0,0x62,0x60,0x83,0xa4,0x17,0x06,0x7b,0xb8,0x0b,0x75,0x30,0x2c,0xd6,0xae,0x40,0x17,0xcd,0xcd,0xb1,0x2e,0xb4,
0x35,0xd0,0xb3,0xd4,0xd1,0xd2,0xd7,0x02,0xb3,0x2c,0x18,0xf8,0x50,0x73,0x2c,0x83,0x9c,0x67,0xb0,0x3f,0xd4,0x3d,0x3a,0x60,0x07,0x81,0xd5,0x99,0xeb,0x40,0xd4,
0x1b,0x33,0xf0,0xa3,0xe5,0x69,0x06,0x41,0x90,0x8b,0x75,0xa0,0x4e,0xd6,0x29,0x4e,0x49,0xce,0x80,0xab,0x81,0x25,0x03,0x06,0xbe,0xd4,0x3c,0xdd,0xd0,0x60,0x9d,
0xd4,0x3c,0xa8,0xa5,0x2c,0xa0,0x3c,0xce,0xc0,0x0f,0x4a,0x08,0x39,0x20,0xa6,0x15,0x30,0xe3,0x19,0x18,0x30,0xb0,0xe5,0x02,0x0b,0x97,0xfc,0x14,0x06,0x66,0x77,
0xd7,0x10,0x06,0xb6,0x62,0x60,0x7a,0xcc,0x4d,0x65,0x60,0xcd,0x28,0x29,0x29,0x28,0x66,0x60,0x06,0x79,0x9c,0x51,0x9f,0x81,0x0b,0x91,0x5b,0x19,0xd2,0x7d,0xf3,
0xab,0x32,0x73,0x72,0x12,0xf5,0x4d,0xf5,0x0c,0x14,0x34,0x00,0x8a,0x30,0x34,0xb4,0x56,0xf0,0xc9,0xcc,0x2b,0xad,0x50,0xa8,0xb0,0x30,0x8b,0x37,0x33,0xd1,0x54,
0x70,0x04,0x7a,0x3e,0x35,0x3c,0x35,0xc9,0x3b,0xb3,0x44,0xdf,0xd4,0xd8,0x44,0xcf,0x18,0xa8,0xcc,0xdb,0x23,0xc4,0xd7,0x47,0x47,0x21,0x27,0x33,0x3b,0x55,0xc1,
0x3d,0x35,0x39,0x3b,0x5f,0x53,0xc1,0x39,0x03,0x58,0xec,0xa4,0xea,0x1b,0x1a,0xe9,0x01,0x7d,0x6a,0x62,0x04,0x52,0x16,0x9c,0x98,0x96,0x58,0x94,0x09,0xd5,0xc4,
0xc0,0x0e,0x0d,0x7c,0x06,0x0e,0x58,0x9c,0x00,0x00,0x00,0x00,0xff,0xff]
>>> struct.pack('BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB', *d1)
"8\xea\xdf\xa2Q\xb2b\xe0b`\x83\xa4\x17\x06{\xb8\x0bu0,\xd6\xae@\x17\xcd\xcd\xb1.\xb45\xd0\xb3\xd4\xd1\xd2\xd7\x02\xb3,\x18\xf8Ps,\x83\x9cg\xb0?\xd4=:`\x07\x81\xd5\x99\xeb@\xd4\x1b3\xf0\xa3\xe5i\x06A\x90\x8bu\xa0N\xd6)NI\xce\x80\xab\x81%\x03\x06\xbe\xd4<\xdd\xd0`\x9d\xd4<\xa8\xa5,\xa0<\xce\xc0\x0fJ\x089 \xa6\x150\xe3\x19\x180\xb0\xe5\x02\x0b\x97\xfc\x14\x06fw\xd7\x10\x06\xb6b`z\xccMe`\xcd())(f`\x06y\x9cQ\x9f\x81\x0b\x91[\x19\xd2}\xf3\xab2sr\x12\xf5M\xf5\x0c\x144\x00\x8a04\xb4V\xf0\xc9\xcc+\xadP\xa8\xb00\x8b73\xd1Tp\x04z>5<5\xc9;\xb3D\xdf\xd4\xd8D\xcf\x18\xa8\xcc\xdb#\xc4\xd7GG!'3;U\xc1=59;_S\xc19\x03X\xec\xa4\xea\x1b\x1a\xe9\x01}jb\x04R\x16\x9c\x98\x96X\x94\t\xd5\xc4\xc0\x0e\r|\x06\x0eX\x9c\x00\x00\x00\x00\xff\xff"
>>> d(struct.pack('BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB', *d1))
'\x00\n\x00\x06accept\x00?text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\x00\x0eaccept-charset\x00\x1eISO-8859-1,utf-8;q=0.7,*;q=0.3\x00\x0faccept-encoding\x00\x11gzip,deflate,sdch\x00\x0faccept-language\x00\x0een-US,en;q=0.8\x00\x04host\x00\x0flocalhost:10000\x00\x06method\x00\x03GET\x00\x06scheme\x00\x05https\x00\x03url\x00\x01/\x00\nuser-agent\x00gMozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.30 (KHTML, like Gecko) Chrome/12.0.742.30 Safari/534.30\x00\x07version\x00\x08HTTP/1.1'
>>> d2 = [0x42,0x8a,0x02,0x66,0x60,0x60,0x0e,0xad,0x60,0xe4,0xd1,0x4f,0x4b,0x2c,0xcb,0x04,0x66,0x33,0x3d,0x20,0x31,0x58,0x42,0x14,0x00,0x00,0x00,0xff,0xff]
>>> struct.pack('BBBBBBBBBBBBBBBBBBBBBBBBBBBBB', *d2)
'B\x8a\x02f``\x0e\xad`\xe4\xd1OK,\xcb\x04f3= 1XB\x14\x00\x00\x00\xff\xff'
>>> d(struct.pack('BBBBBBBBBBBBBBBBBBBBBBBBBBBBB', *d2))
'\x00\n\x00\x06accept\x00\x03*/*\x00\x0eaccept-charset\x00\x1eISO-8859-1,utf-8;q=0.7,*;q=0.3\x00\x0faccept-encoding\x00\x11gzip,deflate,sdch\x00\x0faccept-language\x00\x0een-US,en;q=0.8\x00\x04host\x00\x0flocalhost:10000\x00\x06method\x00\x03GET\x00\x06scheme\x00\x05https\x00\x03url\x00\x0c/favicon.ico\x00\nuser-agent\x00gMozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.30 (KHTML, like Gecko) Chrome/12.0.742.30 Safari/534.30\x00\x07version\x00\x08HTTP/1.1'

OK, so now I can decompress two SPDY packets in node.js and Python. Grrr... Ruby: you are making me so mad.

Working through the Python code to see if I can learn anything, I start with the object initialization:

    def __init__(self, dictionary=None):
        self.dictionary = dictionary
        self.st = _z_stream()
        err = _zlib.inflateInit2_(C.byref(self.st), 15, ZLIB_VERSION, C.sizeof(self.st))
        assert err == Z_OK, err # FIXME: more specific error

The most important bits in there are:

• setting an instance attribute that holds the dictionary
• builds a Z_STREAM
• initializes the Z_STREAM for inflate

The only difference here than what I have seen elsewhere is the inflateInit2 method (instead of the inflateInit). I cannot imagine this makes much of a difference, but it is something to try as I try to get this working in ruby.

The actual decompression takes place in the __call__ method:

    def __call__(self, input):
        outbuf = C.create_string_buffer(CHUNK)
        self.st.avail_in  = len(input)
        self.st.next_in   = C.cast(C.c_char_p(input), C.POINTER(C.c_ubyte))
        self.st.avail_out = CHUNK
        self.st.next_out  = C.cast(outbuf, C.POINTER(C.c_ubyte))
        err = _zlib.inflate(C.byref(self.st), Z_SYNC_FLUSH)
        if err == Z_NEED_DICT:
            assert self.dictionary, "no dictionary provided"  # FIXME: more specific error
            dict_id = _zlib.adler32(
                0L,
                C.cast(C.c_char_p(self.dictionary), C.POINTER(C.c_ubyte)),
                len(self.dictionary)
            )
#            assert dict_id == self.st.adler, 'incorrect dictionary (%s != %s)' % (dict_id, self.st.adler)
            err = _zlib.inflateSetDictionary(
                C.byref(self.st),
                C.cast(C.c_char_p(self.dictionary), C.POINTER(C.c_ubyte)),
                len(self.dictionary)
            )
            assert err == Z_OK, err # FIXME: more specific error
            err = _zlib.inflate(C.byref(self.st), Z_SYNC_FLUSH)
        if err in [Z_OK, Z_STREAM_END]:
            return outbuf[:CHUNK-self.st.avail_out]
        else:
            raise AssertionError, err # FIXME: more specific error

The bulk of the method involves assigning the dictionary, but the important stuff is at the beginning. Each time the decompression was called—as in these cases:

>>> d(struct.pack('B…', *d1))
>>> d(struct.pack('B…', *d2))

...then each of the following occurs:

• a new output buffer is initialized
• Z_STREAM's avail_in is set to the length of the data being decompressed
• Z_STREAM's next_in is set to a pointer to the data itself
• Z_STREAM's avail_out is set to an arbitrary CHUNK size
• Z_STREAM's next_out is set to a pointer to the output buffer
• the stream is inflated (with the dictionary, if necessary)
• the data in the output buffer is returned

As best I can tell, this is exactly what I am doing in Ruby land.

Next I break that down into a pure python script without the object stuff:



That Python code looks very, very similar to my Ruby/FFI code:



They look so similar that I do not see any difference in overall approach. Both hit the above bullet points. Clearly, the syntax that I use for the Ruby version is OK otherwise the first packet would not work. But something just does not translate when I set the next_in pointer to the next packet data in Ruby land.

At this point, I am ready to put ruby on the back burner in favor of node.js. I will continue to try to resolve this in spare time, but I need to make progress in my understanding of SPDY, not just Ruby + FFI idiosyncrasies.

(full gist for ruby & python code)


Day #25

NPM node_modules and Something Completely Different

‹prev | My Chain | next›

A more than slightly frustrating day fiddling with zlib brings me back to node.js land only to find:

➜  ~  npm ls
/home/cstrom
(empty)

Oh, come on! All of my NPM installed modules are kaput?!

Let's re-install the SPDY node.js package:

➜  node git:(master) npm install spdy

> zlibcontext@1.0.7 install /home/cstrom/repos/node/node_modules/spdy/node_modules/zlibcontext
> ./configure && make

Setting srcdir to                        : /home/cstrom/repos/node/node_modules/spdy/node_modules/zlibcontext 
Setting blddir to                        : /home/cstrom/repos/node/node_modules/spdy/node_modules/zlibcontext/build 
Checking for program g++ or c++          : /usr/bin/g++ 
Checking for program cpp                 : /usr/bin/cpp 
Checking for program ar                  : /usr/bin/ar 
Checking for program ranlib              : /usr/bin/ranlib 
Checking for g++                         : ok  
Checking for node path                   : not found 
Checking for node prefix                 : ok /home/cstrom/local/node-v0.5.0-pre 
Checking for library z                   : yes 
'configure' finished successfully (0.209s)
node-waf build
Waf: Entering directory `/home/cstrom/repos/node/node_modules/spdy/node_modules/zlibcontext/build'
[1/2] cxx: src/node_zlib.cc -> build/default/src/node_zlib_1.o
[2/2] cxx_link: build/default/src/node_zlib_1.o -> build/default/zlib_bindings.node
Waf: Leaving directory `/home/cstrom/repos/node/node_modules/spdy/node_modules/zlibcontext/build'
'build' finished successfully (0.519s)
zlibcontext@1.0.7 ./node_modules/spdy/node_modules/zlibcontext
spdy@0.0.1 ./node_modules/spdy

Hrm... What is the deal with the node path not being found? Whatever it is, I am guessing it has something to do with the modules being installed into the current working directory.

After some digging, it turns out that my supposition is wrong. Npm now installs into the current working directory by default. I have been stuck in rvm / ruby land for such a long time that I did not notice the change. The "Checking for node path" message is coming from the zlibcontext configure script (more precisely, node-waf's configuration) and can be safely ignored.

The first thing I need to do is delete all of the node_modules directories that I have created all over the place. I remove a half dozen at various places (apparently this has been confusing me for some time now). With that, I re-run npm install with the --global option:

➜  ~  npm install -g zlibcontext

> zlibcontext@1.0.7 install /home/cstrom/local/node-v0.5.0-pre/lib/node_modules/zlibcontext
> ./configure && make

Setting srcdir to                        : /home/cstrom/local/node-v0.5.0-pre/lib/node_modules/zlibcontext 
Setting blddir to                        : /home/cstrom/local/node-v0.5.0-pre/lib/node_modules/zlibcontext/build 
Checking for program g++ or c++          : /usr/bin/g++ 
Checking for program cpp                 : /usr/bin/cpp 
Checking for program ar                  : /usr/bin/ar 
Checking for program ranlib              : /usr/bin/ranlib 
Checking for g++                         : ok  
Checking for node path                   : not found 
Checking for node prefix                 : ok /home/cstrom/local/node-v0.5.0-pre 
Checking for library z                   : yes 
'configure' finished successfully (0.202s)
node-waf build
Waf: Entering directory `/home/cstrom/local/node-v0.5.0-pre/lib/node_modules/zlibcontext/build'
[1/2] cxx: src/node_zlib.cc -> build/default/src/node_zlib_1.o
[2/2] cxx_link: build/default/src/node_zlib_1.o -> build/default/zlib_bindings.node
Waf: Leaving directory `/home/cstrom/local/node-v0.5.0-pre/lib/node_modules/zlibcontext/build'
'build' finished successfully (0.521s)
zlibcontext@1.0.7 /home/cstrom/local/node-v0.5.0-pre/lib/node_modules/zlibcontext

Ahhh... much better. Now zlibcontext is installed where I can get to it no matter the directory in which I am currently working.

Update: And this was wrong. Subsequent npm ls or attempts to require the packages reveal that this is not how npm 1.x works. Global install is for executable binaries only. Requiring / npm ls (without -g) will not work.

So minor mystery solved, but I am a bit sick of this zlib stuff at this point. So I do a quick inspection of the TLS negotiation of the SSL session involved in SPDY. In a Wireshark capture, there are 2 SSL related packets, the client hello and the server hello:



Of note in there are the cipher suites supported by the client (36 in all are supported by Chrome):



My beloved DES-CBC3-SHA is not in the first 10 shown on the screen capture. In fact it is the last on the list which leads me to believe that my Wireshark / SSL days are going to soon run out.

The only other interesting thing that I note in the request is the server name:



I am not quite certain why the server cares what the client thinks the server name is. Interesting.

As for the server response, I see that my favorite cipher suite is the one being served up by my local SPDY server:



Also of note is the apparently too-new-for-Wireshark TLS extension that performs Next Protocol Negotiation:



The SPDY server needs to respond that it can serve up HTTP/1.1 and HTTP/1.0 in addition to SPDY. For older browsers that do not support SPDY, they will ignore this and proceed to make HTTP requests as normal.

The only other bit of information that is of some interest in there is the certificate itself:



Nothing too surprising, but I am amused by the "International Widget Pty Lmtd" as the organization name. It is a nice default value from openssl.

I will call it a day at this point. I will make one more run at zlibcontext tomorrow -- armed with my newfound NPM knowledge.


Day #24

ZlibContext in Ruby (WIP)

‹prev | My Chain | next›

Even though I have put my 64 bit SPDY issues behind me, I still have a few outstanding questions remaining. The next question is how to resolve this crash in the example server in the SPDY gem:

/home/cstrom/repos/spdy/lib/spdy/compressor.rb:35:in `inflate': invalid stream (RuntimeError)
        from /home/cstrom/repos/spdy/lib/spdy/parser.rb:33:in `unpack_control'
        from /home/cstrom/repos/spdy/lib/spdy/parser.rb:57:in `try_parse'
        from /home/cstrom/repos/spdy/lib/spdy/parser.rb:11:in `<<'
        from npn_spdy_server.rb:47:in `receive_data'
        from /home/cstrom/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/eventmachine.rb:206:in `run_machine'
        from /home/cstrom/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/eventmachine.rb:206:in `run'
        from npn_spdy_server.rb:66:in `<main>'

I have already determined conceptually how to resolve this, with an assist from node-spdy. More specifically, I need to re-use a zlib dictionary when decrompressing subsequent packets on an existing SPDY session.

So I fire up an IRB session in my local SPDY repos and require the SPDY gem stuff:

$: << 'lib' << '../lib'

require 'spdy'

Next I assign arrays of the hex code representation of the packets to local variables:

octets_1 = [0x38,0xea,0xdf,0xa2,0x51,0xb2,0x62,0xe0,0x62,0x60,0x83,0xa4,0x17,0x06,0x7b,0xb8,0x0b,0x75,0x30,0x2c,0xd6,0xae,0x40,0x17,0xcd,0xcd,0xb1,0x2e,0xb4,0x35,0xd0,0xb3,0xd4,0xd1,0xd2,0xd7,0x02,0xb3,0x2c,0x18,0xf8,0x50,0x73,0x2c,0x83,0x9c,0x67,0xb0,0x3f,0xd4,0x3d,0x3a,0x60,0x07,0x81,0xd5,0x99,0xeb,0x40,0xd4,0x1b,0x33,0xf0,0xa3,0xe5,0x69,0x06,0x41,0x90,0x8b,0x75,0xa0,0x4e,0xd6,0x29,0x4e,0x49,0xce,0x80,0xab,0x81,0x25,0x03,0x06,0xbe,0xd4,0x3c,0xdd,0xd0,0x60,0x9d,0xd4,0x3c,0xa8,0xa5,0x2c,0xa0,0x3c,0xce,0xc0,0x0f,0x4a,0x08,0x39,0x20,0xa6,0x15,0x30,0xe3,0x19,0x18,0x30,0xb0,0xe5,0x02,0x0b,0x97,0xfc,0x14,0x06,0x66,0x77,0xd7,0x10,0x06,0xb6,0x62,0x60,0x7a,0xcc,0x4d,0x65,0x60,0xcd,0x28,0x29,0x29,0x28,0x66,0x60,0x06,0x79,0x9c,0x51,0x9f,0x81,0x0b,0x91,0x5b,0x19,0xd2,0x7d,0xf3,0xab,0x32,0x73,0x72,0x12,0xf5,0x4d,0xf5,0x0c,0x14,0x34,0x00,0x8a,0x30,0x34,0xb4,0x56,0xf0,0xc9,0xcc,0x2b,0xad,0x50,0xa8,0xb0,0x30,0x8b,0x37,0x33,0xd1,0x54,0x70,0x04,0x7a,0x3e,0x35,0x3c,0x35,0xc9,0x3b,0xb3,0x44,0xdf,0xd4,0xd8,0x44,0xcf,0x18,0xa8,0xcc,0xdb,0x23,0xc4,0xd7,0x47,0x47,0x21,0x27,0x33,0x3b,0x55,0xc1,0x3d,0x35,0x39,0x3b,0x5f,0x53,0xc1,0x39,0x03,0x58,0xec,0xa4,0xea,0x1b,0x1a,0xe9,0x01,0x7d,0x6a,0x62,0x04,0x52,0x16,0x9c,0x98,0x96,0x58,0x94,0x09,0xd5,0xc4,0xc0,0x0e,0x0d,0x7c,0x06,0x0e,0x58,0x9c,0x00,0x00,0x00,0x00,0xff,0xff]

octets_2 = [0x80,0x02,0x00,0x01,0x01,0x00,0x00,0x27,0x00,0x00,0x00,0x03,0x00,0x00,0x00,0x00,0x80,0x00,0x42,0x8a,0x02,0x66,0x60,0x60,0x0e,0xad,0x60,0xe4,0xd1,0x4f,0x4b,0x2c,0xcb,0x04,0x66,0x33,0x3d,0x20,0x31,0x58,0x42,0x14,0x00,0x00,0x00,0xff,0xff]

d1 = octets_1.pack("C*")
d2 = octets_2.pack("C*")

The actual packets need to be packed into a single string of octets, which can then be decompressed with zlib:

SPDY::Zlib.inflate d1
 => "\x00\n\x00\x06accept\x00?text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\x00\x0Eaccept-charset\x00\x1EISO-8859-1,utf-8;q=0.7,*;q=0.3\x00\x0Faccept-encoding\x00\x11gzip,deflate,sdch\x00\x0Faccept-language\x00\x0Een-US,en;q=0.8\x00\x04host\x00\x0Flocalhost:10000\x00\x06method\x00\x03GET\x00\x06scheme\x00\x05https\x00\x03url\x00\x01/\x00\nuser-agent\x00gMozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.30 (KHTML, like Gecko) Chrome/12.0.742.30 Safari/534.30\x00\aversion\x00\bHTTP/1.1"

And finally, when I attempt to decompress the second packet, I get the same error as before:

SPDY::Zlib.inflate d2
RuntimeError: invalid stream
        from /home/cstrom/repos/spdy/lib/spdy/compressor.rb:35:in `inflate'
        from (irb):19
        from /home/cstrom/.rvm/rubies/ruby-1.9.2-p180/bin/irb:16:in `<main>'

So I try to step down a level to see what I can see. The first thing that SPDY::Zlib.inflate does is build FFI pointer arrays to hold input and ouput data:

# Zlib needs an in-buffer and an out-buffer
# The in-buffer is the compressed data in the first packet
in_buf  = FFI::MemoryPointer.from_string(d1)

# The out-buffer is just a range of memory to store the results
out_buf = FFI::MemoryPointer.new(SPDY::Zlib::CHUNK)

Next up is a zlib Z_STREAM struct. The only important bits for decompressing are next_in, avail_in, next_out, and avail_out:

# z_stream object for zlib
zstream = FFI::Zlib::Z_stream.new
zstream[:next_in]   = in_buf
zstream[:avail_in]  = in_buf.size
zstream[:avail_out] = SPDY::Zlib::CHUNK
zstream[:next_out]  = out_buf

Once the Z_STREAM is ready, I can decompress (a.k.a. inflate) the compressed data:

# Initiate inflate
FFI::Zlib.inflateInit(zstream)

# Try inflate, it fails because it needs a dictionary
FFI::Zlib.inflate(zstream, FFI::Zlib::Z_SYNC_FLUSH)

# Set the dictionary
FFI::Zlib.inflateSetDictionary(zstream, SPDY::Zlib::DICT, SPDY::Zlib::DICT.size)

# Inflate for real now that the dictionary is set
FFI::Zlib.inflate(zstream, FFI::Zlib::Z_SYNC_FLUSH)

And finally, I can read the octets off of the output buffer:

# Uncompressed data is now in the output buffer
out_buf.get_bytes(0, zstream[:total_out])
 => "\x00\n\x00\x06accept\x00?text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\x00\x0Eaccept-charset\x00\x1EISO-8859-1,utf-8;q=0.7,*;q=0.3\x00\x0Faccept-encoding\x00\x11gzip,deflate,sdch\x00\x0Faccept-language\x00\x0Een-US,en;q=0.8\x00\x04host\x00\x0Flocalhost:10000\x00\x06method\x00\x03GET\x00\x06scheme\x00\x05https\x00\x03url\x00\x01/\x00\nuser-agent\x00gMozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.30 (KHTML, like Gecko) Chrome/12.0.742.30 Safari/534.30\x00\aversion\x00\bHTTP/1.1" 

That all works just fine for the first packet in the SPDY connection, but not the second.

The node-spdy code that is able to decompress both packets reuses the same Z_STREAM, including the set dictionary. Each subsequent call to to inflate merely changes the stream attributes (next_in, avail_in, next_out, and avail_out) each time:

Handle ZLibContext::Inflate(const Arguments& args) {                     
//...
  z->inflate_s.next_in = (Bytef*)Buffer::Data(input);                         
  int length = z->inflate_s.avail_in = Buffer::Length(input);                 
//...

    z->inflate_s.avail_out = factor * length;                                 
    z->inflate_s.next_out = (Bytef*)result + compressed;                      
                                                                               
    ret = method(&(z->inflate_s), Z_SYNC_FLUSH);                              
//...
  Buffer* output = Buffer::New(result, compressed);                            
  free(result);                                                                
  return scope.Close(Local::New(output->handle_));                      
}

So let's try to do the same for the second packet in the SPDY gem:

in_buf = FFI::MemoryPointer.from_string(d2)
out_buf = FFI::MemoryPointer.new(SPDY::Zlib::CHUNK)
zstream[:avail_in]  = in_buf.size
zstream[:next_in]   = in_buf
zstream[:avail_out] = SPDY::Zlib::CHUNK
zstream[:next_out]  = out_buf

FFI::Zlib.inflate(zstream, FFI::Zlib::Z_SYNC_FLUSH)
 => -3 

Ew. -3 corresponds to the zlib.h error Z_DATA_ERROR. Ugh.

I attempt a few variations on the z_strem attributes to no avail. Unfortunately, I have to call it a night here. I will pick back up trying guess the right magic incantation to get this working or I may look into another FFI implementation (in python).


Day #23

LD_LIBRARY_PATH in Zsh

‹prev | My Chain | next›

Today I start tying up a few loose ends from my 64 bit eventmachine + edge (NPN-enabled) openssl romp. First up is some confusion over zsh. I have been using zsh (with oh-my-zsh) for several months now. For the most part I like it, though I still have not gotten to the point that I strongly prefer it to bash.

The behavior that I do not quite understand surrounds LD_LIBRARY_PATH. I eventually gave up on zsh while trying to build a local openssl and link other libraries against it. Either LD_LIBRARY_PATH does not do what I think it does (another place for the OS to find shared objects) or zsh is not honoring it in the way that bash does. Granted it was during some very frustrating times, so I could well be conflating other problems, but that is the point—I do not know for sure.

First up, I check out LD_LIBRARY_PATH in bash, which I know I can get to work. If I unset LD_LIBRARY_PATH, then the OS cannot find the libssl version 1.1 against which evenmachine is linked. If I set LD_LIBRARY_PATH, then the OS can find it:

1.9.2@spdy ~/repos/spdy (master)$ export -n LD_LIBRARY_PATH=
1.9.2@spdy ~/repos/spdy (master)$ ldd /home/cstrom/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so
...
        libssl.so.1.1.0 => not found
        libcrypto.so.1.1.0 => not found
...
1.9.2@spdy ~/repos/spdy (master)$ export LD_LIBRARY_PATH=/home/cstrom/local/lib
1.9.2@spdy ~/repos/spdy (master)$ ldd /home/cstrom/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so
...
        libssl.so.1.1.0 => /home/cstrom/local/lib/libssl.so.1.1.0 (0x00007f8727123000)
        libcrypto.so.1.1.0 => /home/cstrom/local/lib/libcrypto.so.1.1.0 (0x00007f8726d59000)
...
1.9.2@spdy ~/repos/spdy (master)$ env | grep LD_LIBRARY_PATH
LD_LIBRARY_PATH=/home/cstrom/local/lib

Everything works as I expect there, which I why I ended up using bash.

So let's try the same thing in zsh:

➜  ~  export LD_LIBRARY_PATH=
➜  ~  ldd /home/cstrom/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so
...
 libssl.so.1.1.0 => not found
 libcrypto.so.1.1.0 => not found
...
➜  ~  export LD_LIBRARY_PATH=/home/cstrom/local/lib
➜  ~  ldd /home/cstrom/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so
...
 libssl.so.1.1.0 => /home/cstrom/local/lib/libssl.so.1.1.0 (0x00007f22c37cb000)
 libcrypto.so.1.1.0 => /home/cstrom/local/lib/libcrypto.so.1.1.0 (0x00007f22c3401000)
...
➜  ~  env | grep LD_LIBRARY_PATH
LD_LIBRARY_PATH=/home/cstrom/local/lib

Hunh?! That is exactly the same behavior as bash.

If nothing else, this is yet more proof that only fools believe what frustration teaches them.

So I take a step back to try to understand why I thought there was a problem. In my .zshrc file, I have the following code that sets various paths for locally installed binaries:

# For locally installed binaries
LD_LIBRARY_PATH=$HOME/local/lib
PATH=$HOME/local/bin:$PATH
PKG_CONFIG_PATH=$HOME/local/lib/pkgconfig
CPATH=$HOME/local/include

# For node.js. For details 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

To the best of my knowledge, I have always done something similar when using bash and have been similarly using this since I switched to zsh. Then again, have I really needed to link against locally installed software with zsh? Have I needed to do it since I upgraded to Ubuntu 11.04?

To the best of my knowledge does not count for much, so I extract the PATHs code into a file named .profile_paths. I then include that file in both my .bashrc and .zshrc files:

source $HOME/.profile_paths

To try them out, I start two interactive sessions using the dash-el option to both zsh and bash, then check to see if my environment holds the necessary information to tell the OS where to find the local shared objects.

In zsh:

➜  ~  zsh -l
➜  ~  env | grep LD_
➜  ~  ldd /home/cstrom/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so
...
 libssl.so.1.1.0 => not found
 libcrypto.so.1.1.0 => not found
...

In bash:

➜  ~  bash -l
1.9.2 ~ $ env | grep LD_
LD_LIBRARY_PATH=/home/cstrom/local/node-v0.5.0-pre/lib:/home/cstrom/local/node-v0.4.7/lib:/home/cstrom/local/node-v0.4.5/lib:/home/cstrom/local/lib
1.9.2 ~ $ ldd /home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so
...
 libssl.so.0.9.8 => /lib/libssl.so.0.9.8 (0x00007f60e26a4000)
 libcrypto.so.0.9.8 => /lib/libcrypto.so.0.9.8 (0x00007f60e2315000)
...

Interesting. So setting LD_LIBRARY_PATH in the .zshrc file does not work whereas setting it in .bashrc does. Presumably, it will work if I explicitly export it into the global namespace—that is something that I have never had to do in the past (because it works as-is in bash).

But, before I verify that, I may as well verify that none of the variables are being set:

➜  ~  env | grep CPATH
CPATH=/home/cstrom/local/node-v0.5.0-pre/include:/home/cstrom/local/node-v0.4.7/include:/home/cstrom/local/node-v0.4.5/include:/home/cstrom/local/include

Hunh? CPATH is set but LD_LIBRARY_PATH is not? In fact, all of the variables from .profile_paths are in my zsh environment—except for LD_LIBRARY_PATH.

And yes, if I export LD_LIBRARY_PATH:

export LD_LIBRARY_PATH=$HOME/local/lib

...then zsh sees LD_LIBRARY_PATH:

➜  ~  env | grep LD_
➜  ~  zsh -l
➜  ~  env | grep LD_
LD_LIBRARY_PATH=/home/cstrom/local/node-v0.5.0-pre/lib:/home/cstrom/local/node-v0.4.7/lib:/home/cstrom/local/node-v0.4.5/lib:/home/cstrom/local/lib
➜  ~  ldd /home/cstrom/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so
...
 libssl.so.1.1.0 => /home/cstrom/local/lib/libssl.so.1.1.0 (0x00007fccb8bb0000)
 libcrypto.so.1.1.0 => /home/cstrom/local/lib/libcrypto.so.1.1.0 (0x00007fccb87e7000)
...

As best my google-fu can tell, this behavior is undocumented. It is certainly annoying.


Day #22

Finally 64 bit Ruby SPDY

‹prev | My Chain | next›

Up today, I hope to verify that I have put behind my 64 bit woes behind for good. Specifically, I hope that yesterday's magical configuration settings for openssl will translate into a working TLS/NPN enabled eventmachine—more specifically Carson McDonald's tls-npn fork.

So, back in my local copy of the tls-npn fork, I try to install the gem:

➜  eventmachine git:(tls-npn) gem install pkg/eventmachine-1.0.0.beta.3.gem
Building native extensions.  This could take a while...
Successfully installed eventmachine-1.0.0.beta.3
1 gem installed

Wow. More than a bit anti-climatic. Surely it can't just work.

It doesn't.

It starts OK, but accessing the server results in:

➜  examples git:(master) ✗ ruby npn_spdy_server.rb                                     
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/em/connection.rb:404:in `set_negotiable_protocols': undefined method `set_negotiable_protocols' for EventMachine:Module (NoMethodError)
        from npn_spdy_server.rb:35:in `post_init'
        from /home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/em/connection.rb:45:in `block in new'
        from /home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/em/connection.rb:36:in `instance_eval'
        from /home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/em/connection.rb:36:in `new'
        from /home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/eventmachine.rb:1415:in `event_callback'
        from /home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/eventmachine.rb:206:in `run_machine'
        from /home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/eventmachine.rb:206:in `run'
        from npn_spdy_server.rb:66:in `<main>'

Hrm... aw nuts. I forgot to rebuild ruby with the new openssl install:

rvm remove 1.9.2
rvm install 1.9.2 -C --with-openssl-dir=$HOME/local

I reinstall the packages needed for the SPDY gem and eventmachine:

gem install rake-compiler rspec bundler bindata ffi-zlib

Finally, I fire up the sample npn_spdy_server from Carson McDonald, and access it with a web browser:

➜  examples git:(master) ✗ ruby npn_spdy_server.rb
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/em/connection.rb:414: [BUG] Segmentation fault
ruby 1.9.2p0 (2010-08-18 revision 29036) [x86_64-linux]

-- control frame ----------
c:0009 p:---- s:0029 b:0029 l:000028 d:000028 CFUNC  :get_negotiated_protocol
c:0008 p:0020 s:0025 b:0025 l:000024 d:000024 METHOD /home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/em/connection.rb:414
c:0007 p:0011 s:0022 b:0022 l:000021 d:000021 METHOD npn_spdy_server.rb:41
c:0006 p:---- s:0018 b:0018 l:000017 d:000017 FINISH
c:0005 p:---- s:0016 b:0016 l:000015 d:000015 CFUNC  :run_machine
c:0004 p:0248 s:0013 b:0013 l:000012 d:000012 METHOD /home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/eventmachine.rb:206
c:0003 p:0070 s:0006 b:0006 l:0013d8 d:000c58 EVAL   npn_spdy_server.rb:66
c:0002 p:---- s:0004 b:0004 l:000003 d:000003 FINISH
c:0001 p:0000 s:0002 b:0002 l:0013d8 d:0013d8 TOP
---------------------------
-- Ruby level backtrace information ----------------------------------------
npn_spdy_server.rb:66:in `<main>'
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/eventmachine.rb:206:in `run'
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/eventmachine.rb:206:in `run_machine'
npn_spdy_server.rb:41:in `ssl_handshake_completed'
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/em/connection.rb:414:in `get_negotiated_protocol'
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/em/connection.rb:414:in `get_negotiated_protocol'

-- C level backtrace information -------------------------------------------
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(rb_vm_bugreport+0x5f) [0x7fb4cce97ebf]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(+0x5fc7e) [0x7fb4ccd77c7e]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(rb_bug+0xa2) [0x7fb4ccd78ba2]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(+0x1132d5) [0x7fb4cce2b2d5]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xfc60) [0x7fb4ccb09c60]
/lib/x86_64-linux-gnu/libc.so.6(memcpy+0xa0) [0x7fb4cbf26a00]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(+0x11ff7f) [0x7fb4cce37f7f]
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so(+0x1c774) [0x7fb4cb4dc774]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(+0x179cee) [0x7fb4cce91cee]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(+0x16f816) [0x7fb4cce87816]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(+0x175c53) [0x7fb4cce8dc53]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(+0x176ef4) [0x7fb4cce8eef4]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(rb_funcall+0xc2) [0x7fb4cce8fb32]
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so(+0x1d4ac) [0x7fb4cb4dd4ac]
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so(_ZN20ConnectionDescriptor20_DispatchInboundDataEPKci+0x83) [0x7fb4cb4d2fb3]
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so(_ZN20ConnectionDescriptor4ReadEv+0x9c) [0x7fb4cb4d309c]
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so(_ZN14EventMachine_t14_RunSelectOnceEv+0x2da) [0x7fb4cb4d6aba]
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so(_ZN14EventMachine_t8_RunOnceEv+0x28) [0x7fb4cb4d7c88]
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so(_ZN14EventMachine_t3RunEv+0x5c) [0x7fb4cb4d9a8c]
/home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so(+0x1c9e9) [0x7fb4cb4dc9e9]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(+0x179cee) [0x7fb4cce91cee]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(+0x16f816) [0x7fb4cce87816]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(+0x175c53) [0x7fb4cce8dc53]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(rb_iseq_eval_main+0xb1) [0x7fb4cce931c1]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(+0x660ba) [0x7fb4ccd7e0ba]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(ruby_exec_node+0x1d) [0x7fb4ccd7f01d]
/home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9(ruby_run_node+0x1e) [0x7fb4ccd8122e]
ruby(main+0x4b) [0x40094b] 
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xff) [0x7fb4cbebaeff]
ruby() [0x400839]

[NOTE]
You may have encountered a bug in the Ruby interpreter or extension libraries.
Bug reports are welcome.   
For details: http://www.ruby-lang.org/bugreport.html

[1]    16613 abort      ruby npn_spdy_server.rb

Holy cow.

Just when I think I have this all sorted out. Wow.

It turns out that, despite removing and rebuilding ruby with my local openssl libraries, ruby and eventmachine still do not know about the local openssl libraries:

1.9.2@spdy ~/repos/spdy/examples (master)$ ldd /home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so
        linux-vdso.so.1 =>  (0x00007fff363ff000)
        libruby.so.1.9 => /home/cstrom/.rvm/rubies/ruby-1.9.2-p0/lib/libruby.so.1.9 (0x00007f1831b40000)
        libssl.so.0.9.8 => /lib/libssl.so.0.9.8 (0x00007f18318c7000)
        libcrypto.so.0.9.8 => /lib/libcrypto.so.0.9.8 (0x00007f1831537000)
        libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007f1831319000)
        librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00007f1831111000)
        libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007f1830f0c000)
        libcrypt.so.1 => /lib/x86_64-linux-gnu/libcrypt.so.1 (0x00007f1830cd3000)
        libstdc++.so.6 => /usr/lib/x86_64-linux-gnu/libstdc++.so.6 (0x00007f18309cd000)
        libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007f1830747000)
        libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f18303b3000)
        libgcc_s.so.1 => /lib/x86_64-linux-gnu/libgcc_s.so.1 (0x00007f183019d000)
        /lib64/ld-linux-x86-64.so.2 (0x00007f1832188000)
        libz.so.1 => /lib/x86_64-linux-gnu/libz.so.1 (0x00007f182ff84000)

Bah!

My next step is to upgrade RVM rvm to the latest released version. This allows me to install ruby 1.9.2-p180 instead of the 1.9.2-p0 I had been using. With that, I re-run through the entire install procedure:

export PATH=$HOME/local/bin/:$PATH
export LD_LIBRARY_PATH=$HOME/local/lib
export PKG_CONFIG_PATH=$HOME/local/lib/pkgconfig
export CPATH=$HOME/local/include

rvm install 1.9.2 -C --with-openssl-dir=$HOME/local
rvm use ruby-1.9.2-p180
rvm --default use 1.9.2-p180
rvm gemset create spdy
gem install rake-compiler rspec bundler bindata ffi-zlib

cd ~/repos/eventmachine/
rake clean
rake gem
gem install pkg/eventmachine-1.0.0.beta.3.gem

With that, I finally have an eventmachine linked against my local, npn-enabled openssl libraries:

1.9.2@spdy ~/repos/spdy/examples (master)$ ldd /home/cstrom/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/rubyeventmachine.so
 linux-vdso.so.1 =>  (0x00007fffb0bef000)
 libruby.so.1.9 => /home/cstrom/.rvm/rubies/ruby-1.9.2-p180/lib/libruby.so.1.9 (0x00007fe8e8c4d000)
 libssl.so.1.1.0 => /home/cstrom/local/lib/libssl.so.1.1.0 (0x00007fe8e89ea000)
 libcrypto.so.1.1.0 => /home/cstrom/local/lib/libcrypto.so.1.1.0 (0x00007fe8e8620000)
 libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007fe8e83f6000)
 libz.so.1 => /lib/x86_64-linux-gnu/libz.so.1 (0x00007fe8e81de000)
 libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007fe8e7fbf000)
 librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00007fe8e7db7000)
 libcrypt.so.1 => /lib/x86_64-linux-gnu/libcrypt.so.1 (0x00007fe8e7b7e000)
 libstdc++.so.6 => /usr/lib/x86_64-linux-gnu/libstdc++.so.6 (0x00007fe8e7877000)
 libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007fe8e75f2000)
 libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007fe8e725e000)
 libgcc_s.so.1 => /lib/x86_64-linux-gnu/libgcc_s.so.1 (0x00007fe8e7047000)

Finally, I retry the npn_spdy_server:

1.9.2@spdy ~/repos/spdy/examples (master)$ ruby npn_spdy_server.rb 
[:SPDY, :connection_closed]
[:SPDY, :connection_closed]
[:SPDY, :connection_closed]
[:SPDY_HEADERS, {"accept"=>"text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8", "accept-charset"=>"ISO-8859-1,utf-8;q=0.7,*;q=0.3", "accept-encoding"=>"gzip,deflate,sdch", "accept-language"=>"en-US,en;q=0.8", "host"=>"localhost:10000", "method"=>"GET", "scheme"=>"https", "url"=>"/", "user-agent"=>"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.35 (KHTML, like Gecko) Chrome/13.0.761.0 Safari/534.35", "version"=>"HTTP/1.1"}]
[:SPDY, :sent, :SYN_REPLY]
[:SPDY, :sent, :DATA]
[:SPDY, :sent, :DATA_FIN]
[:SPDY, :connection_closed]
/home/cstrom/repos/spdy/lib/spdy/compressor.rb:35:in `inflate': invalid stream (RuntimeError)
 from /home/cstrom/repos/spdy/lib/spdy/parser.rb:33:in `unpack_control'
 from /home/cstrom/repos/spdy/lib/spdy/parser.rb:57:in `try_parse'
 from /home/cstrom/repos/spdy/lib/spdy/parser.rb:11:in `<<'
 from npn_spdy_server.rb:47:in `receive_data'
 from /home/cstrom/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/eventmachine.rb:206:in `run_machine'
 from /home/cstrom/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/eventmachine.rb:206:in `run'
 from npn_spdy_server.rb:66:in `<main>'

Yay! Never have I been so glad to see an error message. Because, it the browser, I see:



The error message is solved in node.js, but still need to fix it here in ruby. Another day.


Day #21