Sniffing SPDY with ssldump

‹prev | My Chain | next›

Up today, I would like to mess about with SPDY over SSL. Last night, I was able to play around a bit with the eventmachine example implementation in the SPDY gem. I even got to inspect SPDY packets with tcpdump.

The only thing lacking from last night's experiment was SSL—a necessary component of SPDY. Tonight I hope to repeat that success with ssldump.

First, I re-enable the start_tls line in the example eventmachine code. I then open the application which now resides at: https://localhost:10000/.

I get a warning that the certificate is not trusted, but proceed anyway only to get... nothing. The browser never receives a result, though the event machine server kindly reports:

[:SPDY, :connection_closed]

This message indicates that the browser has unbound the connection:

  def unbind
    p [:SPDY, :connection_closed]
  end

Hrm...

Next up, I actually follow the instructions in the example server and start Chrome with the --use-spdy=ssl. According to the SPDY debugging page, this option "forces Chrome to always use SPDY, even if not negotiated over SSL". That actually does the trick:



Interesting. So if the debugging page is correct, then the reason this works is that, otherwise the connection is made while negotiating over plain text. That is something to investigate another day.

For today, if I am going to sniff SSL packets, I am going to need a server certificate. The whole point of SSL, of course, is to make packet sniffing impossible (or at least prohibitively difficult). It is possible, however, if you have the server's private key. To make one, I use openssl:

➜  spdy git:(master)     openssl genrsa -out key.pem 1024
Generating RSA private key, 1024 bit long modulus
.........................................................++++++
.........................++++++
e is 65537 (0x10001)
➜  spdy git:(master) ✗ openssl req -new -key key.pem -out request.pem
You are about to be asked to enter information that will be incorporated
into your certificate request.
What you are about to enter is what is called a Distinguished Name or a DN.
There are quite a few fields but you can leave some blank
For some fields there will be a default value,
If you enter '.', the field will be left blank.
-----
Country Name (2 letter code) [AU]:US
State or Province Name (full name) [Some-State]:Maryland
Locality Name (eg, city) []:Baltimore
Organization Name (eg, company) [Internet Widgits Pty Ltd]:
Organizational Unit Name (eg, section) []:
Common Name (eg, YOUR name) []:Chris Strom
Email Address []:chris@eeecomputes.com

Please enter the following 'extra' attributes
to be sent with your certificate request
A challenge password []:password
An optional company name []:
➜  spdy git:(master) ✗ openssl x509 -req -days 30 -in request.pem -signkey key.pem -out cert.pem
Signature ok
subject=/C=US/ST=Maryland/L=Baltimore/O=Internet Widgits Pty Ltd/CN=Chris Strom/emailAddress=chris@eeecomputes.com
Getting Private key

To use that in eventmachine, I change the start_tls:

  def post_init
    @parser = SPDY::Parser.new
    @parser.on_headers_complete do |stream_id, associated_stream, priority, headers|
      # ...
    end

    #start_tls
    start_tls(:private_key_file => 'key.pem', :cert_chain_file => 'cert.pem', :verify_peer => false)
  end

After restarting the server, I verify that I can still access the example SPDY site. Once I am confident that everything still works with the new certificate, I am ready to try out ssldump:

sudo ssldump -k key.pem -i lo -dX

The -k option uses the same private key file that I just generated and that eventmachine is now using. The example server is listening on localhost, so I need to sniff the packets on the loopback interface, lo. The -dX option tells ssldump to dump the packet contents in hex—ideally this is exactly what I did last night using tcpdump, but now I will be able to see an (almost) real SPDY conversation take place.

And, sure enough, that does the trick:

➜  examples git:(master) ✗ sudo ssldump -k key.pem -i lo -dX
New TCP connection #1: localhost.localdomain(35098) <-> localhost.localdomain(10000)
New TCP connection #2: localhost.localdomain(35099) <-> localhost.localdomain(10000)
1 1  0.0071 (0.0071)  C>S  Handshake
      ClientHello
        Version 3.1
...
3 7  0.0040 (0.0000)  C>S  Handshake3 8  0.0040 (0.0000)  C>S  application_data
    ---------------------------------------------------------------
    00 2c 01 d3 fe 80 02 00 01 01 00 01 24 00 00 00
    01 00 00 00 00 00 00 38 ea df a2 51 b2 62 e0 61
    60 83 a4 17 06 7b b8 0b 75 30 2c d6 ae 40 17 cd
    cd b1 2e b4 35 d0 b3 d4 d1 d2 d7 02 b3 2c 18 f8
    50 73 2c 83 9c 67 b0 3f d4 3d 3a 60 07 81 d5 99
    eb 40 d4 1b 33 f0 a3 e5 69 06 41 90 8b 75 a0 4e
    d6 29 4e 49 ce 80 ab 81 25 03 06 be d4 3c dd d0
    60 9d d4 3c a8 a5 bc 28 89 8d 81 23 2f 5f 17 2c
    c2 c0 02 ca fc 0c fc a0 14 92 03 62 5a 01 73 a4
    81 01 03 5b 2e b0 d4 c9 4f 61 60 76 77 0d 61 60
    2b 28 4a 4c cf 4d 44 d2 c5 56 0c 24 73 53 19 58
    33 4a 4a 0a 8a 19 98 41 61 c4 a8 cf 00 10 17 22
    63 33 a4 fb e6 57 65 e6 e4 24 ea 9b ea 19 28 68
    44 18 1a 5a 2b f8 64 e6 95 56 28 54 58 98 c5 9b
    99 68 2a 38 02 c3 29 35 3c 35 c9 3b b3 44 df d4
    d8 44 cf 18 a8 cc db 23 c4 d7 47 47 21 27 33 3b
    55 c1 3d 35 39 3b 5f 53 c1 39 03 58 42 a5 ea 1b
    1a e9 01 03 c5 c4 48 cf d0 48 21 38 31 2d b1 28
    13 aa 89 81 1d 1a 4f 0c 1c b0 e8 03 00 00 00 ff
    ff 00 00 00 ff ff
    ---------------------------------------------------------------
...

The fourth byte in bold indicates that this is a SYN_STREAM just like I saw last night.

That is a good place to stop for the night. Hopefully I will not have to rely on this technique much while working with SPDY, but it is good to know that it is available if needed.


SPDY protocol (draft 2)

Day #6

Low Level SPDY Debugging

‹prev | My Chain | next›

In response to my pull request on the SPDY gem, Ilya mentioned that the SPDY version that he saw in the packets was 2—despite Draft #2 of the SPDY protocol stating that it ought to be 1. That got me wondering, how does one see real SPDY packets?

I half hoped to see this in the Network section of the Developer tools. No such luck.

My next stop is the Events tab on the chrome://net-internals page in Chrome. There, I see:

www.google.com:443 (DIRECT)

Start Time: Fri Apr 29 2011 16:56:10 GMT-0400 (EDT)

(P) t=1304110570969 [st=       0] +SPDY_SESSION  [dt=?]
                                   --> host = "www.google.com:443"
                                   --> proxy = "DIRECT"
(P) t=1304110570969 [st=       0]     SPDY_SESSION_SEND_SETTINGS  
                                      --> settings = ["[4:100]"]
(P) t=1304110570971 [st=       2]     SPDY_SESSION_RECV_SETTINGS  
                                      --> settings = ["[4:100]"]
(P) t=1304113104957 [st= 2533988]     SPDY_SESSION_SEND_RST_STREAM  
                                      --> status = 5
                                      --> stream_id = 175
(P) t=1304113461199 [st= 2890230]     SPDY_SESSION_SYN_STREAM  
                                      --> flags = 1
                                      --> accept: */*
                                          accept-charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
                                          accept-encoding: gzip,deflate,sdch
                                          accept-language: en-US,en;q=0.8
                                          cookie: [value was stripped]
                                          host: www.google.com
                                          method: GET
                                          scheme: https
                                          url: /voice/b/0/request/unread/?b=0
                                          user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.30 (KHTML, like Gecko) Chrome/12.0.742.9 Safari/534.30
                                          version: HTTP/1.1
                                      --> id = 201
(P) t=1304113461266 [st= 2890297]     SPDY_SESSION_SYN_REPLY  
                                      --> flags = 0
                                      --> cache-control: no-cache, no-store, must-revalidate
                                          content-disposition: attachment
                                          content-encoding: gzip
                                          content-length: 148
                                          content-type: text/javascript; charset=UTF-8
                                          date: Fri, 29 Apr 2011 21:44:21 GMT
                                          expires: Fri, 01 Jan 1990 00:00:00 GMT
                                          pragma: no-cache, no-store
                                          server: GSE
                                          status: 200 OK
                                          version: HTTP/1.1
                                          x-content-type-options: nosniff
                                          x-frame-options: SAMEORIGIN
                                          x-xss-protection: 1; mode=block
                                      --> id = 201
(P) t=1304113461271 [st= 2890302]     SPDY_SESSION_RECV_DATA  
                                      --> flags = 0
                                      --> size = 148
                                      --> stream_id = 201

Nice. That looks to be a SPDY session between the Google Voice extension and the Google servers. In there, I see all the fields that I have come to know and love over the past couple of days. This looks to be an invaluable tool in debugging SPDY sessions. Except...

I do not see the SPDY version in any of those packets. So what do I do if I need to do even lower level debugging than this?

I quickly scan through the tool and debugging page from the SPDY project. That does not seem to be of much help because it suggests that the Network tab in the Developer Tools ought to support SPDY debugging, which it does not. I give the Speed Tracer extension a whirl, but it also does not include SPDY information.

It seems that I am stuck with good old tcpdump, which is a fairly nice place to be stuck. To use it, though, I need to turn off SSL in examples/spdy_server.rb of the SPDY gem:

...
  def post_init
    @parser = SPDY::Parser.new
    @parser.on_headers_complete do |stream_id, associated_stream, priority, headers|
      #...
    end

#    start_tls
  end

I also need to start Chrome without SSL in SPDY:

google-chrome --use-spdy=no-ssl

Lastly, I start a tcpdump session:

➜  spdy git:(master) ✗ sudo tcpdump -i lo -X -s0 port 10000
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes

And load the page. In the tcpdump output, I see:

...
23:23:11.696498 IP localhost.localdomain.webmin > localhost.localdomain.33000: Flags [P.], seq 1:91, ack 305, win 265, options [nop,nop,TS val 33869373 ecr 33869372], length 90
        0x0000:  4500 008e 1038 4000 4006 2c30 7f00 0001  E....8@.@.,0....
        0x0010:  7f00 0001 2710 80e8 7f76 de0b 7f7f d955  ....'....v.....U
        0x0020:  8018 0109 fe82 0000 0101 080a 0204 ce3d  ...............=
        0x0030:  0204 ce3c 8002 0002 0000 0035 0000 0009  ...<.......5....
        0x0040:  0000 78bb dfa2 51b2 6260 66e0 7186 0652  ..x...Q.b`f.q..R
        0x0050:  0830 9018 b810 7630 b041 9433 b001 93b1  .0....v0.A.3....
        0x0060:  82bf 3703 3b54 2303 07cc 3c00 0000 00ff  ..7.;T#...<.....
        0x0070:  ff00 0000 0900 0000 0d54 6869 7320 6973  .........This.is
        0x0080:  2053 5044 592e 0000 0009 0100 0000       .SPDY.........
...

I am most interested in the first four bytes of the bold section, 8002. The control bit at the very beginning of the SYN_REPLY generates the 8. The remaining 002 is the version of the protocol being used, which is, indeed, version 2, not 1 as the Draft Specification says.

Just to be sure I am looking at the right bit of information, the next 4 bytes, 0002 should contain the message type. In the case of a SYN_REPLY, it should be 2—which it is—so I am definitely looking at the right response here.

Similarly, the SYN_STREAM from the browser sends 8002 0001 so even the browser is sending version 2.

In the grand scheme of things, whether it is version 1 or 2 does not make much difference. I am content knowing that I have a mechanism to troubleshoot this stuff at a very low level. I just hope I do not have to make a habit of it.

Before moving on with my exploration, I think I will give ssldump a whirl. It would be nice to be able to see the same information without the special Chrome flags. I will pick back up there tomorrow.

Day #5

RSpec Driven PING Packets

‹prev | My Chain | next›

With a bit of experience assembling SPDY frame with the SPDY gem, tonight I will attempt to build additional frames.

Currently, the gem is capable of SYN_STREAM and SYN_REPLY control frames. The other frames in Draft #2 of the SPDY protocol include: RST_STREAM, SETTINGS, NOOP, PING, GOAWAY, HEADERS, and WINDOW_UPDATE.

I start with an easy (but potentially useful) one: PING. The PING frame looks like:

  +----------------------------------+
  |1|       1          |       6     |
  +----------------------------------+
  | 0 (flags) |     4 (length)       |
  +----------------------------------|
  |            32-bit ID             |
  +----------------------------------+

Or, in RSpec format:

  context "PING" do
    describe "the assembled packet" do
      specify "starts with a control bit"
      specify "followed by the version (1)"
      specify "followed by the type (6)"
      specify "followed by flags (0)"
      specify "followed by the length (always 4)"
    end
  end

The definition of those specify statements can be as follows:

  context "PING" do
    describe "the assembled packet" do
      before do
        @ping = SPDY::Protocol::Control::Ping.new
        @ping.create(:stream_id => 1)
        @frame = @ping.to_binary_s
      end
      specify "starts with a control bit" do
        @frame[0].should == "\x80"
      end
      specify "followed by the version (1)" do
        @frame[1].should == "\x01"
      end
      specify "followed by the type (6)" do
        @frame[2..3].should == "\x00\x06"
      end
      specify "followed by flags (0)" do
        @frame[4].should == "\x00"
      end
      specify "followed by the length (always 4)" do
        @frame[5..7].should == "\x00\x00\x04"
      end
    end
  end

The first expectation is a bit of a cheat. The first bit is a control bit (which is on), but I am testing the resulting first two bytes (1000 0000 == 128 = \x80). I need to come up with a better scheme for that (maybe just rely on bindata's implementation?), but that will suffice to drive implementation today. The remaining expectations are straight forward.

Implementing those specs is similarly straight forward (largely thanks to the Bindata gem):

      class Ping < BinData::Record
        bit1 :frame, :initial_value => CONTROL_BIT
        bit15 :version, :initial_value => VERSION
        bit16 :type, :value => 6

        bit8 :flags, :value => 0
        bit24 :len, :value => 4

        bit32 :stream_id

        def create(opts = {})
          self.stream_id = opts.fetch(:stream_id, 1)
          self
        end
      end

Unfortunately, I cannot use the Header class already in the SPDY gem. It expects the stream ID to be 31 bits. Oddly, the specification for PING packets is 32 bits (all other control frames are 31). Similarly, I cannot use the Helpers mixin, both because it is coupled with the Header implementation and because it expects a data section (no data in a PING). Regardless, the Bindata gem makes for a very clean implementation.

As for parsing a PING:

  context "PING" do
    it "can parse a PING packet" do
      ping = SPDY::Protocol::Control::Ping.new
      ping.parse(PING)

      ping.stream_id.should == 1
      ping.type.should == 6

      ping.to_binary_s.should == PING
    end

Where the PING constant is defined as:

PING = "\x80\x01\x00\x06\x00\x00\x00\x04\x00\x00\x00\x01"

The implementation is trivial (again, thanks to Bindata):

        def parse(chunk)
          self.read(chunk)
          self
        end

With that, I have a nice, executable specification for the SPDY PING packet:

➜  spdy git:(master) rspec ./spec/protocol_spec.rb:149 -cfs
Run filtered using {:line_number=>149}

SPDY::Protocol
  PING
    can parse a PING packet
    the assembled packet
      starts with a control bit
      followed by the version (1)
      followed by the type (6)
      followed by flags (0)
      followed by the length (always 4)

Finished in 0.00509 seconds
6 examples, 0 failures

I spend a little time knocking out the RST_STREAM frame and then call it a night.

Day #4

Deep Dive into SPDY SYN_REPLY and NV Packets

‹prev | My Chain | next›

Today, I pick back up with my exploration of the SPDY gem. After mistakenly getting started on Ruby 1.8.7 last night, I have decided that might not be such a bad idea. There are a few failures under 1.8.7 and fixing them ought to help me wrap my brain around this.

Continuing with my fork of the gem, I have the following failures:

➜  spdy git:(master) ✗ rspec ./spec/protocol_spec.rb -cfs

SPDY::Protocol
  NV
    should create an NV packet (FAILED - 1)
  SYN_STREAM
    should create a SYN_STREAM packet
    should parse SYN_STREAM packet
  SYN_REPLY
    should create a SYN_REPLY packet (FAILED - 2)
    should parse SYN_REPLY packet
  DATA
    should create a data frame
    should create a FIN data frame
    should read a FIN data frame

Failures:

  1) SPDY::Protocol NV should create an NV packet
     Failure/Error: nv.to_binary_s.should == NV
       expected: "\000\003\000\fContent-Type\000\ntext/plain\000\006status\000\006200 OK\000\aversion\000\bHTTP/1.1"
            got: "\000\003\000\fContent-Type\000\ntext/plain\000\aversion\000\bHTTP/1.1\000\006status\000\006200 OK" (using ==)
       Diff:
       @@ -1,3 +1,3 @@
        Content-Type
       -text/plainstatus200 OKversioHTTP/1.1
       +text/plainversioHTTP/1.1status200 OK
     # ./spec/protocol_spec.rb:10

  2) SPDY::Protocol SYN_REPLY should create a SYN_REPLY packet
     Failure/Error: sr.to_binary_s.should == SYN_REPLY
       expected: "\200\002\000\002\000\000\0005\000\000\000\001\000\000x\273\337\242Q\262b`f\340q\206\006R\b0\220\030\270\020v0\260A\2243\260\001\223\261\202\2777\003;T#\003\a\314<\000\000\000\000\377\377"
            got: "\200\002\000\002\000\000\0005\000\000\000\001\000\000x\273\337\242Q\262b`f\340q\206\006R\b0\220\030\270\020v0\260C\0252p\300\3643\260AL``\003\246l\005\177o\000\000\000\000\377\377" (using ==)
     # ./spec/protocol_spec.rb:63

Finished in 0.02327 seconds

The first looks to be a simple hash ordering problem (hashes in 1.8.7 do not retain order as in 1.9). The length of the strings is identical and it appears that the status and version key-value pairs are switched.

Since I cannot rely on hash order, I instead test the components of a SPDY name-value (NV) message. Per the SPDY protocol (draft 2), NV blocks look like:

  +------------------------------------+
  | Number of Name/Value pairs (int16) |
  +------------------------------------+
  |     Length of name (int16)         |
  +------------------------------------+
  |           Name (string)            |
  +------------------------------------+
  |     Length of value  (int16)       |
  +------------------------------------+
  |          Value   (string)          |
  +------------------------------------+
  |           (repeats)                |

The block starts with 2 bytes (int16). Then for the first name-value pair, another 2 bytes (int16) for the length of the name, the name itself, another int16 for the length of the value, then the value. The name-values then repeat until there are no more name-value pairs. An RSpec expectation for such a situation might read:

it "has 2 bytes (total number of name-value pairs) + 2 bytes for each name (length of name) + 2 bytes for each value (length of value) + names + values"

To implement that expectation, I go with:

  context "NV" do
    describe "creating a packet" do
      before do
        nv = SPDY::Protocol::NV.new

        @name_values = {'version' => 'HTTP/1.1', 'status' => '200 OK', 'Content-Type' => 'text/plain'}
        nv.create(@name_values)

        @binary_string = nv.to_binary_s
      end

      it "has 2 bytes (total number of name-value pairs) + 2 bytes for each name (length of name) + 2 bytes for each value (length of value) + names + values" do
        num_size_bytes = 2 + @name_values.size * (2 + 2)

        @binary_string.length.should ==
          @name_values.inject(num_size_bytes) {|sum, kv| sum + kv[0].length + kv[1].length}
      end
    end

Most of that is adapted from the failing spec. Instead of testing the end result, @binary_string, against a pre-built expectation, I check that its length is what I expect it to be per the protocol's working draft. That's a longish expectation string, but it is still kinda cool to think that the draft specification can be built from executable examples.

With that passing, I build more specs to verify that the individual sections of the NV block are what I expect:

      it "begins with the number of name-value pairs" do
        @binary_string[0..1].should == "\x00\x03"
      end

      it "prefaces names with the length of the name" do
        @binary_string.should =~ %r{\x00\x0cContent-Type}
      end
      it "prefaces values with the length of the value" do
        @binary_string.should =~ %r{\x00\x08HTTP/1.1}
      end

With those passing, the NV protocol spec output now reads:

SPDY::Protocol
  NV
    creating a packet
      begins with the number of name-value pairs
      prefaces names with the length of the name
      prefaces values with the length of the value
      has 2 bytes (total number of name-value pairs) + 2 bytes for each name (length of name) + 2 bytes for each value (length of value) + names + values

I kinda like that. And, best of all, it runs on both 1.8.7 and 1.9.

So what is up with the SYN failure?

  1) SPDY::Protocol SYN_REPLY should create a SYN_REPLY packet
     Failure/Error: sr.to_binary_s.should == SYN_REPLY
       expected: "\200\002\000\002\000\000\0005\000\000\000\001\000\000x\273\337\242Q\262b`f\340q\206\006R\b0\220\030\270\020v0\260A\2243\260\001\223\261\202\2777\003;T#\003\a\314<\000\000\000\000\377\377"
            got: "\200\002\000\002\000\000\0005\000\000\000\001\000\000x\273\337\242Q\262b`f\340q\206\006R\b0\220\030\270\020v0\260C\0252p\300\3643\260AL``\003\246l\005\177o\000\000\000\000\377\377" (using ==)
     # ./spec/protocol_spec.rb:85

I run through similar deconstruction of the assembled packet expectation until I get this output:

  SYN_REPLY
    should parse SYN_REPLY packet
    creating a packet  
      common control frame fields
        is version 1 (FAILED - 1)
        is type 2
        has empty flags
      type specific frame fields
        has a stream id
        has data
        should > 50
      assembled packet
        starts with a control bit
        followed by the version (FAILED - 2)
        followed by the type
        followed by flags
        followed by the length
        followed by the stream ID
        followed by unused space

The two failures are because (I think) the SPDY gem gets the protocol version wrong. Even though the current working draft for SPDY is #2, the protocol version is still one:

  +----------------------------------+
  |1|        1        |        2     |
  +----------------------------------+
  | Flags (8)  |  Length (24 bits)   |
  +----------------------------------+
  |X|          Stream-ID (31bits)    |
  +----------------------------------+
  | Unused        |                  |
  +----------------                  |
  |     Name/value header block      |
  |              ...                 |

The fix is easy enough—update the code such that VERSION = 1.

The last bit that I need to specify is the part that is failing back in 1.8.7. Both the expectation and the actual result look like gobbledygook because they are compressed (SPDY is all about saving space):

  1) SPDY::Protocol SYN_REPLY should create a SYN_REPLY packet
     Failure/Error: sr.to_binary_s.should == SYN_REPLY
       expected: "\200\002\000\002\000\000\0005\000\000\000\001\000\000x\273\337\242Q\262b`f\340q\206\006R\b0\220\030\270\020v0\260A\2243\260\001\223\261\202\2777\003;T#\003\a\314<\000\000\000\000\377\377"
            got: "\200\002\000\002\000\000\0005\000\000\000\001\000\000x\273\337\242Q\262b`f\340q\206\006R\b0\220\030\270\020v0\260C\0252p\300\3643\260AL``\003\246l\005\177o\000\000\000\000\377\377" (using ==)
     # ./spec/protocol_spec.rb:85

So, to test, I verify that part of the headers that are being compressed are in the inflated NV block:

  context "SYN_REPLY" do
    describe "creating a packet" do
      before do
        @sr = SPDY::Protocol::Control::SynReply.new

        headers = {'Content-Type' => 'text/plain', 'status' => '200 OK', 'version' => 'HTTP/1.1'}
        @sr.create(:stream_id => 1, :headers => headers)
      end

      describe "assembled packet" do
        before do
          @packet = @sr.to_binary_s
        end

#....

        specify "followed by compressed NV data" do
          data = SPDY::Zlib.inflate(@packet[14..-1].to_s)
          data.should =~ %r{\x00\x0cContent-Type}
        end
      end
    end
  end

With that, I have the entire spec passing under both ruby 1.8.7 and 1.9:

SPDY::Protocol
  SYN_REPLY
    should parse SYN_REPLY packet
    creating a packet
      common control frame fields
        is version 1
        is type 2
        has empty flags
      type specific frame fields
        has a stream id
        has data
        should > 50
      assembled packet
        starts with a control bit
        followed by the version
        followed by the type
        followed by flags
        followed by the length
        followed by the stream ID
        followed by unused space
        followed by compressed NV data

Passing and close to the draft specification.

I will review and send a pull request tomorrow. I have no idea if 1.8.7 compatibility matters to Ilya or if he will appreciate the significant increase in verbosity. If nothing else, the version (one, even in Draft #2) ought to be addressed.

Day #3

SPDY Gem and Ruby 1.8.7

‹prev | My Chain | next›

After last night's no-go with mod_spdy, I quickly move onto the SPDY gem. I still have a weak grasp on SPDY, so I want to stick as close as possible to my comfort zone during my initial exploration. For me, that means ruby.

Luckily, Ilya Grigorik has already done pioneering here.

First up, I fork his repo on github. I would not normally do that while exploring a gem, but, I need to make changes if I hope to realize the scope of my chain. So, I clone my forked repository down to my local machine:

➜  repos  git clone git@github.com:eee-c/spdy.git                                                                                             Cloning into spdy...
                                 
remote: Counting objects: 213, done.
remote: Compressing objects: 100% (107/107), done.
remote: Total 213 (delta 109), reused 181 (delta 93)
Receiving objects: 100% (213/213), 25.58 KiB, done.
Resolving deltas: 100% (109/109), done.

In the gem, I see that Ilya has a Gemfile for bundler:

➜  spdy git:(master) ✗ ls
examples  Gemfile  lib  Rakefile  README.md  spdy.gemspec  spec

Nice. I like to use rvm to keep my gem environments clean, so I create a .rvmrc file:

rvm use default@spdy

Once I execute that, I can bundle install the prerequisites:

➜  spdy git:(master) ✗ bundle install
Fetching source index for http://rubygems.org/
Installing rake (0.8.7)
Installing bindata (1.3.1)
Installing diff-lcs (1.1.2)
Installing ffi (1.0.7) with native extensions
Installing ffi-zlib (0.2.0)
Installing rspec-core (2.5.1)
Installing rspec-expectations (2.5.0)
Installing rspec-mocks (2.5.0)
Installing rspec (2.5.0)
Using spdy (0.0.2) from source at /home/cstrom/repos/spdy
Using bundler (1.0.9)
Your bundle is complete! It was installed into /home/cstrom/.rvm/gems/ree-1.8.7-2010.02@spdy

Nice! Working with gems is a pleasure in a gem like this.

I do notice that I am using ruby enterprise enterprise edition (1.8.7 and not 1.9) as my default ruby. I do not know how that happened, but I need to keep that in mind in case anything goes wrong.

Since there are specs, I think I'll start with some of them:

➜  spdy git:(master) rspec ./spec/protocol_spec.rb -cfs
/home/cstrom/repos/spdy/lib/spdy/protocol.rb:43: field 'type' shadows an existing method in SPDY::Protocol::Control::Header (NameError)
        from /home/cstrom/.rvm/rubies/ree-1.8.7-2010.02/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `gem_original_require'
        from /home/cstrom/.rvm/rubies/ree-1.8.7-2010.02/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `require'
        from /home/cstrom/repos/spdy/lib/spdy.rb:4
        from /home/cstrom/.rvm/rubies/ree-1.8.7-2010.02/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `gem_original_require'
        from /home/cstrom/.rvm/rubies/ree-1.8.7-2010.02/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `require'
        from /home/cstrom/repos/spdy/spec/helper.rb:2
        from /home/cstrom/.rvm/rubies/ree-1.8.7-2010.02/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `gem_original_require'
        from /home/cstrom/.rvm/rubies/ree-1.8.7-2010.02/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `require'
        from /home/cstrom/repos/spdy/spec/protocol_spec.rb:1
...

Yikes!

I am not familiar with "shadows an existing method in", but Google suggests that the bindata gem might be the culprit.

Since I have nothing but gems related to SPDY installed in my rvm gemset, I can ack-grep through all of my gems for the term "shadows":

➜  gems  ack shadows                          
bindata-1.3.1/lib/bindata/dsl.rb
254:          if name_shadows_method?(name)
255:            dsl_raise NameError.new("", name), "field '#{name}' shadows an existing method"
295:      def name_shadows_method?(name)

...

bindata-1.3.1/spec/struct_spec.rb
29:  it "should fail when field name shadows an existing method" do

Sure enough, this is the bindata gem.

Before trying anything else, let's see if this is a ruby 1.8.7 vs 1.9.2 issue:

➜  spdy git:(master) rvm use 1.9.2@spdy
Using /home/cstrom/.rvm/gems/ruby-1.9.2-p0 with gemset spdy
➜  spdy git:(master) gem install bundler
Successfully installed bundler-1.0.12
1 gem installed
➜  spdy git:(master) bundle install
Fetching source index for http://rubygems.org/
Installing rake (0.8.7) 
Installing bindata (1.3.1) 
Installing diff-lcs (1.1.2) 
Installing ffi (1.0.7) with native extensions 
Installing ffi-zlib (0.2.0) 
Installing rspec-core (2.5.1) 
Installing rspec-expectations (2.5.0) 
Installing rspec-mocks (2.5.0) 
Installing rspec (2.5.0) 
Using spdy (0.0.2) from source at . 
Using bundler (1.0.12) 
Your bundle is complete! It was installed into /home/cstrom/.rvm/gems/ruby-1.9.2-p0@spdy

➜  spdy git:(master) rspec ./spec/protocol_spec.rb -cfs

SPDY::Protocol
  NV
    should create an NV packet
  SYN_STREAM
    should create a SYN_STREAM packet
    should parse SYN_STREAM packet
  SYN_REPLY
    should create a SYN_REPLY packet
    should parse SYN_REPLY packet
  DATA
    should create a data frame
    should create a FIN data frame
    should read a FIN data frame

Finished in 0.02769 seconds
8 examples, 0 failures

Yup, it works just fine in 1.9.

I could just move on with 1.9.2, but I opt to investigate why this is not working in 1.8.7. I check to see if the class in question is being double loaded:

...
      class Header < BinData::Record
        puts "I'm being loaded!"

        hide :u1
...

But I only see the one load:

➜  spdy git:(master) rspec ./spec/protocol_spec.rb -cfs
I'm being loaded!
/home/cstrom/repos/spdy/lib/spdy/protocol.rb:45: field 'type' shadows an existing method in SPDY::Protocol::Control::Header (NameError)
        from /home/cstrom/.rvm/rubies/ree-1.8.7-2010.02/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `gem_original_require'
        from /home/cstrom/.rvm/rubies/ree-1.8.7-2010.02/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `require'
        from /home/cstrom/repos/spdy/lib/spdy.rb:4
...

Hey wait, why is it only failing on the type attribute? Other attributes are defined before it. What's special about type....? Damn.

And then it dawns on me: type is a method on Object in ruby 1.8.

Ugh. If it were up to me, I would stick with calling the field type because that stays closer to the SPDY draft specification. Besides, Object#type is deprecated in 1.8.7. It may end up being too difficult to maintain, but this compatibility library mostly gets the specs passing without altering the 1.9 goodness:

if Object.instance_methods.include? "type"
  class BinData::DSLMixin::DSLParser
    def name_is_reserved_in_1_8?(name)
      return false if name == "type"
      name_is_reserved_in_1_9?(name)
    end
    alias_method :name_is_reserved_in_1_9?, :name_is_reserved?
    alias_method :name_is_reserved?, :name_is_reserved_in_1_8?

    def name_shadows_method_in_1_8?(name)
      return false if name == "type"
      name_shadows_method_in_1_9?(name)
    end
    alias_method :name_shadows_method_in_1_9?, :name_shadows_method?
    alias_method :name_shadows_method?, :name_shadows_method_in_1_8?
  end
end

For both name_is_reserved? and name_shadows_method? in the DSLParser class, I return false for "type" (i.e. the "type" name is not reserved and the "type" method is not being shadowed).

That gets most of the specs passing:

➜  spdy git:(master) ✗ rspec ./spec/protocol_spec.rb -cfs

SPDY::Protocol
  NV
    should create an NV packet (FAILED - 1)
  SYN_STREAM
    should create a SYN_STREAM packet
    should parse SYN_STREAM packet
  SYN_REPLY
    should create a SYN_REPLY packet (FAILED - 2)
    should parse SYN_REPLY packet
  DATA
    should create a data frame
    should create a FIN data frame
    should read a FIN data frame

Failures:

  1) SPDY::Protocol NV should create an NV packet
     Failure/Error: nv.to_binary_s.should == NV
       expected: "\000\003\000\fContent-Type\000\ntext/plain\000\006status\000\006200 OK\000\aversion\000\bHTTP/1.1"
            got: "\000\003\000\fContent-Type\000\ntext/plain\000\aversion\000\bHTTP/1.1\000\006status\000\006200 OK" (using ==)
       Diff:
       @@ -1,3 +1,3 @@
        Content-Type
       -text/plainstatus200 OKversioHTTP/1.1
       +text/plainversioHTTP/1.1status200 OK
     # ./spec/protocol_spec.rb:10

  2) SPDY::Protocol SYN_REPLY should create a SYN_REPLY packet
     Failure/Error: sr.to_binary_s.should == SYN_REPLY
       expected: "\200\002\000\002\000\000\0005\000\000\000\001\000\000x\273\337\242Q\262b`f\340q\206\006R\b0\220\030\270\020v0\260A\2243\260\001\223\261\202\2777\003;T#\003\a\314<\000\000\000\000\377\377"
            got: "\200\002\000\002\000\000\0005\000\000\000\001\000\000x\273\337\242Q\262b`f\340q\206\006R\b0\220\030\270\020v0\260C\0252p\300\3643\260AL``\003\246l\005\177o\000\000\000\000\377\377" (using ==)
     # ./spec/protocol_spec.rb:63

Finished in 0.02327 seconds

The two failures look to be hash ordering related. In 1.9, ruby hashes are ordered, where in 1.8 they are effectively random. I believe the specs need to be adjusted to handle potentially random-ordered hashes (unless Ilya wants to make the gem 1.9-only).

I will pick back up with that tomorrow.

Day #2

Don't Bother with This Post, but Do Give mod_spdy a Try!

‹prev | My Chain | next›

Update: It seems as though you should bother with mod_spdy nowadays (2011-12-22). Per the comments below, mod_spdy is again being actively maintained again. Yay!

Tonight, I am going to see how far along I can get with mod_spdy, the SPDY module for Apache. I expect that most of my work with SPDY will be in the form of node.js or Ruby implementations, but Apache affords me a nice level of comfort with respect to simply serving up files.

I get myself off to an auspicious start:

➜  spdy  sudo apt-get install subversion
[sudo] password for cstrom:
Reading package lists... Done
Building dependency tree
Reading state information... Done
Suggested packages:
subversion-tools db4.8-util
The following NEW packages will be installed:
subversion
0 upgraded, 1 newly installed, 0 to remove and 8 not upgraded.
Need to get 298 kB of archives.
After this operation, 1,257 kB of additional disk space will be used.
Get:1 http://us.archive.ubuntu.com/ubuntu/ natty/main subversion amd64 1.6.12dfsg-4ubuntu2 [298 kB]
Fetched 298 kB in 3s (85.5 kB/s)
Selecting previously deselected package subversion.
(Reading database ... 242860 files and directories currently installed.)
Unpacking subversion (from .../subversion_1.6.12dfsg-4ubuntu2_amd64.deb) ...
Processing triggers for man-db ...
Setting up subversion (1.6.12dfsg-4ubuntu2) ...

With that out of the way, I can download the "depot tools" source code, which I install into ~/repos/spdy:

➜  spdy  svn co http://src.chromium.org/svn/trunk/tools/depot_tools
A    depot_tools/git-cl
A    depot_tools/README.gclient
A    depot_tools/WATCHLISTS
A    depot_tools/README.codereview
A    depot_tools/git_cl.py
...
A    depot_tools/wtf
...
A    depot_tools/zsh-goodies
A    depot_tools/zsh-goodies/_gclient
A    depot_tools/zsh-goodies/README
...
A    depot_tools/cpplint.bat
A    depot_tools/hammer.bat
U   depot_tools
Checked out revision 82936.

(gotta love a codebase with an wtf file)

Again in ~repos/spdy, I install :

➜  spdy  mkdir mod_spdy
➜  spdy  cd mod_spdy
➜  mod_spdy  ../depot_tools/gclient config http://mod-spdy.googlecode.com/svn/trunk/src
➜  mod_spdy  ls
➜  mod_spdy  ls -a
.  ..  .gclient

Strange. This is my first experience with gclient, but I expected more to happen than just creating a .gclient file:

➜  mod_spdy  cat .gclient 
solutions = [
{ "name"        : "src",
"url"         : "http://mod-spdy.googlecode.com/svn/trunk/src",
"custom_deps" : {
},
"safesync_url": "",
},
]

It seems the real magic is in the update sub-command, which installs a lot of stuff:

➜  mod_spdy  ../depot_tools/gclient update --force

________ running 'svn checkout http://mod-spdy.googlecode.com/svn/trunk/src /home/cstrom/repos/spdy/mod_spdy/src --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/build
A    /home/cstrom/repos/spdy/mod_spdy/src/build/common.gypi
A    /home/cstrom/repos/spdy/mod_spdy/src/build/gyp_chromium
...
U   /home/cstrom/repos/spdy/mod_spdy/src
Checked out revision 143.
Syncing projects:   5% ( 1/18)
________ running 'svn checkout http://src.chromium.org/svn/trunk/src/net/tools/flip_server@46690 /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/net/tools/flip_server --revision 46690 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/net/tools/flip_server/split.cc
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/net/tools/flip_server/balsa_enums.h
...
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/net/tools/flip_server/ring_buffer.h
Checked out revision 46690.
Syncing projects:  11% ( 2/18)
________ running 'svn checkout http://src.chromium.org/svn/trunk/src/base@46690 /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/base --revision 46690 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/base/windows_message_list.h
...
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/base/debug_message.cc
U   /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/base
Checked out revision 46690.
Syncing projects:  16% ( 3/18)

________ running 'svn checkout http://svn.apache.org/repos/asf/apr/apr/tags/1.4.2@head /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/apr/src --revision head --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/apr/src/config.layout
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/apr/src/Makefile.in
...
/home/cstrom/repos/spdy/mod_spdy/src/tools/grit/grit.py
A    /home/cstrom/repos/spdy/mod_spdy/src/tools/grit/README
Checked out revision 46690.
Syncing projects:  27% ( 5/18)
________ running 'svn checkout http://src.chromium.org/svn/trunk/src/testing@46690 /home/cstrom/repos/spdy/mod_spdy/src/testing --revision 46690 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/testing/README.chromium
A    /home/cstrom/repos/spdy/mod_spdy/src/testing/gmock
...
A    /home/cstrom/repos/spdy/mod_spdy/src/testing/gmock_mutant.h
U   /home/cstrom/repos/spdy/mod_spdy/src/testing
Checked out revision 46690.
Syncing projects:  33% ( 6/18)

________ running 'svn checkout http://svn.apache.org/repos/asf/httpd/httpd/tags/2.2.15/include@head /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/httpd/src/include --revision head --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/httpd/src/include/ap_regex.h
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/httpd/src/include/util_time.h
...
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/httpd/src/include/http_request.h
U   /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/httpd/src/include
Checked out revision 1096629.
Syncing projects:  38% ( 7/18)
________ running 'svn checkout http://src.chromium.org/svn/trunk/src/third_party/protobuf2@46690 /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2 --revision 46690 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/__init__.py
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/descriptor_pb2.py
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/config.h
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/protobuf.gyp
U   /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2
Checked out revision 46690.
Syncing projects:  44% ( 8/18)
________ running 'svn checkout http://protobuf.googlecode.com/svn/trunk@327 /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/src --revision 327 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/src/post_process_dist.sh
...
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/src/examples/Makefile
U   /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/src
Checked out revision 327.
Syncing projects:  50% ( 9/18)
________ running 'svn checkout http://src.chromium.org/svn/trunk/src/tools/data_pack@46690 /home/cstrom/repos/spdy/mod_spdy/src/tools/data_pack --revision 46690 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/tools/data_pack/repack.py
A    /home/cstrom/repos/spdy/mod_spdy/src/tools/data_pack/scons.py
A    /home/cstrom/repos/spdy/mod_spdy/src/tools/data_pack/data_pack.py
U   /home/cstrom/repos/spdy/mod_spdy/src/tools/data_pack
Checked out revision 46690.
Syncing projects:  55% (10/18)
________ running 'svn checkout http://src.chromium.org/svn/trunk/src/third_party/scons@46690 /home/cstrom/repos/spdy/mod_spdy/src/third_party/scons --revision 46690 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/scons/README.chromium
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/scons/scons-README
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/scons/scons-LICENSE
...
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/scons/scons-local/SCons/Tool/cc.py
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/scons/scons-local/SCons/Tool/dvips.py
Checked out revision 46690.
Syncing projects:  61% (11/18)
________ running 'svn checkout http://gyp.googlecode.com/svn/trunk@818 /home/cstrom/repos/spdy/mod_spdy/src/tools/gyp --revision 818 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/tools/gyp/test
A    /home/cstrom/repos/spdy/mod_spdy/src/tools/gyp/test/additional-targets
...
A    /home/cstrom/repos/spdy/mod_spdy/src/tools/gyp/codereview.settings
A    /home/cstrom/repos/spdy/mod_spdy/src/tools/gyp/DEPS
Checked out revision 818.
Syncing projects:  66% (12/18)


________ running 'svn checkout http://googletest.googlecode.com/svn/trunk@408 /home/cstrom/repos/spdy/mod_spdy/src/testing/gtest --revision 408 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/testing/gtest/test
A    /home/cstrom/repos/spdy/mod_spdy/src/testing/gtest/test/gtest_break_on_failure_unittest_.cc
...
A    /home/cstrom/repos/spdy/mod_spdy/src/testing/gtest/CMakeLists.txt
Checked out revision 408.
Syncing projects:  72% (13/18)
________ running 'svn checkout http://svn.apache.org/repos/asf/httpd/httpd/tags/2.2.15/os@head /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/httpd/src/os --revision head --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/httpd/src/os/Makefile.in
...
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/httpd/src/os/.indent.pro
U   /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/httpd/src/os
Checked out revision 1096630.
Syncing projects:  77% (14/18)
________ running 'svn checkout http://src.chromium.org/svn/trunk/src/third_party/zlib@46690 /home/cstrom/repos/spdy/mod_spdy/src/third_party/zlib --revision 46690 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/zlib/README.chromium
...
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/zlib/infback.c
U   /home/cstrom/repos/spdy/mod_spdy/src/third_party/zlib
Checked out revision 46690.
Syncing projects:  83% (15/18)
________ running 'svn checkout http://src.chromium.org/svn/trunk/src/site_scons/site_tools@46690 /home/cstrom/repos/spdy/mod_spdy/src/site_scons/site_tools --revision 46690 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/site_scons/site_tools/chromium_builders.py
U   /home/cstrom/repos/spdy/mod_spdy/src/site_scons/site_tools
Checked out revision 46690.
Syncing projects:  88% (16/18)
________ running 'svn checkout http://src.chromium.org/svn/trunk/src/build@46690 /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/build --revision 46690 --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/build/README.chromium
...
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/build/apply_locales.py
U   /home/cstrom/repos/spdy/mod_spdy/src/third_party/chromium/src/build
Checked out revision 46690.
Syncing projects:  94% (17/18)

________ running 'svn checkout http://svn.apache.org/repos/asf/apr/apr-util/tags/1.3.9@head /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/aprutil/src --revision head --force --ignore-externals' in '/home/cstrom/repos/spdy/mod_spdy'
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/aprutil/src/ldap
...
A    /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/aprutil/src/libaprutil.rc
U   /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/aprutil/src
Checked out revision 1096632.
Syncing projects: 100% (18/18), done.

________ running '/usr/bin/python src/build/gyp_chromium' in '/home/cstrom/repos/spdy/mod_spdy'
Updating projects from gyp files...
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/aprutil/include.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/py_proto.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/protobuf_lite.host.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/apr/include.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/zlib/zlib.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/base/base.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/testing/gtest.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/protobuf_lite.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/protobuf.host.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/apr/apr.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/httpd/include.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/net/spdy.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/testing/gtestmain.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/testing/gmock.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/protoc.host.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/aprutil/aprutil.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/mod_diagnostics/mod_diagnostics.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/mod_spdy/spdy_common.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/testing/gmockmain.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/base/base_unittests.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/net/spdy_test.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/mod_static/http_response_proto.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/mod_spdy/spdy_common_test.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/mod_spdy/spdy_apache.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/mod_static/mod_static.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/mod_spdy/mod_spdy.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/build/All.target.mk
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/protobuf2/protobuf.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/apr/apr.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/mod_static/mod_static.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/httpd/httpd.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/apache/aprutil/aprutil.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/net/net.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/zlib/zlib.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/testing/gtest.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/third_party/mod_diagnostics/mod_diagnostics.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/base/base.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/build/all.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/mod_spdy/mod_spdy.Makefile
Generating /home/cstrom/repos/spdy/mod_spdy/src/testing/gmock.Makefile

Whoa. So gclient is apparently some kind of subversion wrapper with extensions for managing svn:external. Hopefully I won't need to learn too much more about it.

Next, I attempt to compile the code:

➜  mod_spdy  cd src
➜  src  make
CC(target) out/Debug/obj.target/base/third_party/chromium/src/base/setproctitle_linux.o
CXX(target) out/Debug/obj.target/base/base/string16.o
CXX(target) out/Debug/obj.target/base/third_party/chromium/src/base/third_party/dmg_fp/dtoa.o
CXX(target) out/Debug/obj.target/base/third_party/chromium/src/base/third_party/dmg_fp/g_fmt.o
CXX(target) out/Debug/obj.target/base/third_party/chromium/src/base/at_exit.o
CXX(target) out/Debug/obj.target/base/third_party/chromium/src/base/debug_util.o
CXX(target) out/Debug/obj.target/base/third_party/chromium/src/base/debug_util_posix.o
CXX(target) out/Debug/obj.target/base/third_party/chromium/src/base/lock.o
CXX(target) out/Debug/obj.target/base/third_party/chromium/src/base/lock_impl_posix.o
CXX(target) out/Debug/obj.target/base/base/logging.o
...
CXX(target) out/Debug/obj.target/protobuf_lite/third_party/protobuf2/src/src/google/protobuf/stubs/hash.o
In file included from /usr/include/c++/4.5/ext/hash_map:60:0,
from third_party/protobuf2/src/src/google/protobuf/stubs/hash.h:43,
from third_party/protobuf2/src/src/google/protobuf/stubs/hash.cc:33:
/usr/include/c++/4.5/backward/backward_warning.h:28:2: warning: #warning This file includes at least one deprecated or antiquated header which may be removed without further notice at a future date. Please use a non-deprecated interface with equivalent functionality instead. For a listing of replacement headers and interfaces, consult the file backward_warning.h. To disable this warning use -Wno-deprecated.
CXX(target) out/Debug/obj.target/protobuf_lite/third_party/protobuf2/src/src/google/protobuf/extension_set.o
In file included from /usr/include/c++/4.5/ext/hash_map:60:0,
from third_party/protobuf2/src/src/google/protobuf/stubs/hash.h:43,
from third_party/protobuf2/src/src/google/protobuf/extension_set.cc:35:
/usr/include/c++/4.5/backward/backward_warning.h:28:2: warning: #warning This file includes at least one deprecated or antiquated header which may be removed without further notice at a future date. Please use a non-deprecated interface with equivalent functionality instead. For a listing of replacement headers and interfaces, consult the file backward_warning.h. To disable this warning use -Wno-deprecated.
CXX(target) out/Debug/obj.target/protobuf_lite/third_party/protobuf2/src/src/google/protobuf/generated_message_util.o
...
RULE http_response_proto_genproto_0 out/Debug/obj/gen/protoc_out/mod_static/http_response.pb.h
TOUCH out/Debug/obj.target/mod_static/http_response_proto.stamp
CXX(target) out/Debug/obj.target/mod_static/mod_static/mod_static.o
CXX(target) out/Debug/obj.target/mod_static/gen/protoc_out/mod_static/http_response.pb.o
SOLINK(target) out/Debug/obj.target/mod_static/libmod_static.so
COPY out/Debug/libmod_static.so
CXX(target) out/Debug/obj.target/spdy_test/net/spdy/spdy_protocol_test.o
cc1plus: warnings being treated as errors
net/spdy/spdy_protocol_test.cc: In member function ‘virtual void::SpdyProtocolTest_FrameStructs_Test::TestBody()’:
net/spdy/spdy_protocol_test.cc:64:3: error: converting ‘false’ to pointer type for argument 1 of ‘char testing::internal::IsNullLiteralHelper(testing::internal::Secret*)’
net/spdy/spdy_protocol_test.cc:70:3: error: converting ‘false’ to pointer type for argument 1 of ‘char testing::internal::IsNullLiteralHelper(testing::internal::Secret*)’
net/spdy/spdy_protocol_test.cc: At global scope:
net/spdy/spdy_protocol_test.cc:40:1: error: ‘<unnamed>::SpdyProtocolTest_ProtocolConstants_Test::test_info_’ defined but not used
net/spdy/spdy_protocol_test.cc:58:1: error: ‘<unnamed>::SpdyProtocolTest_FrameStructs_Test::test_info_’ defined but not used
net/spdy/spdy_protocol_test.cc:73:1: error: ‘::SpdyProtocolTest_DataFrameStructs_Test::test_info_’ defined but not used
net/spdy/spdy_protocol_test.cc:79:1: error: ‘::SpdyProtocolTest_ControlFrameStructs_Test::test_info_’ defined but not used
net/spdy/spdy_protocol_test.cc:125:1: error: ‘<unnamed>::SpdyProtocolTest_TestDataFrame_Test::test_info_’ defined but not used
net/spdy/spdy_protocol_test.cc:168:1: error: ‘::SpdyProtocolTest_TestSpdySettingsFrame_Test::test_info_’ defined but not used
net/spdy/spdy_protocol_test.cc:217:1: error: ‘::SpdyProtocolDeathTest_TestDataFrame_Test::test_info_’ defined but not used
net/spdy/spdy_protocol_test.cc:234:1: error: ‘::SpdyProtocolDeathTest_TestSpdyControlFrameStreamId_Test::test_info_’ defined but not used
net/spdy/spdy_protocol_test.cc:249:1: error: ‘::SpdyProtocolDeathTest_TestSpdyControlFrameVersion_Test::test_info_’ defined but not used
net/spdy/spdy_protocol_test.cc:270:1: error: ‘::SpdyProtocolDeathTest_TestSpdyControlFrameType_Test::test_info_’ defined but not used
make: *** [out/Debug/obj.target/spdy_test/net/spdy/spdy_protocol_test.o] Error 1

Gah!

It seems I have run afowl of life on the bleeding edge: Issue 16: Build failure using GCC 4.5.2 on Gentoo.

I started out with mod_spdy to retain some comfort level. Given that, I am not going to try to investigate C++ errors (at least not tonight). Instead... to the VM!

Specifically, I retrace my steps on an Ubuntu 10.10 VM:

chris@chris-VirtualBox:~/spdy/mod_spdy/src$ make
...
CXX(target) out/Debug/obj.target/spdy_test/net/spdy/spdy_framer_test.o
LINK(target) out/Debug/spdy_test
CC(target) out/Debug/obj.target/mod_diagnostics/third_party/mod_diagnostics/mod_diagnostics.o
third_party/mod_diagnostics/mod_diagnostics.c: In function ‘diagnostic_ofilter’:
third_party/mod_diagnostics/mod_diagnostics.c:73: warning: format not a string literal and no format arguments
third_party/mod_diagnostics/mod_diagnostics.c: In function ‘diagnostic_ifilter’:
third_party/mod_diagnostics/mod_diagnostics.c:102: warning: format ‘%d’ expects type ‘int’, but argument 10 has type ‘apr_off_t’
SOLINK(target) out/Debug/obj.target/third_party/mod_diagnostics/libmod_diagnostics.so
COPY out/Debug/libmod_diagnostics.so
TOUCH out/Debug/obj.target/build/All.stamp

I guess that qualifies as success. At least it didn't exit with an error code.

Lacking any documentation, I locate what looks to be an Apache module in mod_spdy/src/out/Debug:

chris@chris-VirtualBox:~/spdy/mod_spdy/src/out/Debug$ ls *so
libmod_diagnostics.so  libmod_spdy.so  libmod_static.so

So I copy libmod_spdy.so to /usr/lib/apache2/modules/:

chris@chris-VirtualBox:~/spdy/mod_spdy/src/out/Debug$ sudo cp libmod_spdy.so /usr/lib/apache2/modules/

I then create a load file, spdy.load:

chris@chris-VirtualBox:/etc/apache2/mods-available$ cat spdy.load 
LoadModule spdy_module /usr/lib/apache2/modules/libmod_spdy.so

And, finally enable that module:

chris@chris-VirtualBox:/etc/apache2/mods-enabled$ cd /etc/apache2/mods-enabled/
chris@chris-VirtualBox:/etc/apache2/mods-enabled$ sudo ln -s ../mods-available/spdy.load 

With that, I get a nice little warning about an experimental module when I restart apache:

chris@chris-VirtualBox:/etc/apache2/mods-enabled$ sudo /etc/init.d/apache2 restart
* Restarting web server apache2
[Mon Apr 25 23:50:52 2011] [warn] [0425/235052:WARNING:mod_spdy/mod_spdy.cc(203)] mod_spdy is currently an experimental Apache module. It is not yet suitable for production environments and may have stability issues.
... waiting [Mon Apr 25 23:50:53 2011] [warn] [0425/235053:WARNING:mod_spdy/mod_spdy.cc(203)] mod_spdy is currently an experimental Apache module. It is not yet suitable for production environments and may have stability issues.
...done.

Nice. But does it work?

The answer to that, unfortunately is a resounding no. Attempting to access the web server—either via Chrome or curl proves fruitless. In the apache error log, I find:

[Mon Apr 25 23:35:06 2011] [warn] [0425/233506:WARNING:net/spdy/spdy_framer.cc(243)] Unexpectedly large frame.  Spdy session is likely corrupt.
[0425/233506:FATAL:mod_spdy/common/spdy_stream_distributor.cc(62)] Check failed: false. 
Backtrace:
/usr/lib/apache2/modules/libmod_spdy.so(StackTrace::StackTrace()+0x2c) [0x6062fe]
/usr/lib/apache2/modules/libmod_spdy.so(+0x272b2) [0x5ff2b2]
/usr/lib/apache2/modules/libmod_spdy.so(logging::LogMessage::~LogMessage()+0x7d) [0x608137]
/usr/lib/apache2/modules/libmod_spdy.so(mod_spdy::SpdyStreamDistributor::OnError(spdy::SpdyFramer*)+0x88) [0x6287b2]
/usr/lib/apache2/modules/libmod_spdy.so(spdy::SpdyFramer::set_error(spdy::SpdyFramer::SpdyError)+0xd5) [0x621617]
/usr/lib/apache2/modules/libmod_spdy.so(spdy::SpdyFramer::ProcessDataFramePayload(char const*, unsigned int)+0x173) [0x622343]
/usr/lib/apache2/modules/libmod_spdy.so(spdy::SpdyFramer::ProcessInput(char const*, unsigned int)+0x1e6) [0x62186e]
/usr/lib/apache2/modules/libmod_spdy.so(mod_spdy::SpdyFramePump::PumpAtMost(unsigned int)+0x139) [0x627987]
/usr/lib/apache2/modules/libmod_spdy.so(mod_spdy::SpdyFramePump::PumpMoreBytes()+0x18e) [0x627740]
/usr/lib/apache2/modules/libmod_spdy.so(mod_spdy::SpdyFramePump::PumpOneFrame()+0x33) [0x62754b]
/usr/lib/apache2/modules/libmod_spdy.so(mod_spdy::SpdyInputFilter::Read(ap_filter_t*, apr_bucket_brigade*, ap_input_mode_t, apr_read_type_e, long long)+0x100) [0x600152]
/usr/lib/apache2/modules/libmod_spdy.so(+0x26968) [0x5fe968]
/usr/sbin/apache2(ap_get_brigade+0x43) [0x79cf13]
/usr/sbin/apache2(ap_rgetline_core+0xa1) [0x7837b1]
/usr/sbin/apache2(ap_read_request+0x261) [0x784191]
/usr/sbin/apache2(+0x43fde) [0x7a0fde]
/usr/sbin/apache2(ap_run_process_connection+0x61) [0x7999c1]
/usr/sbin/apache2(+0x4db4b) [0x7aab4b]
/usr/lib/libapr-1.so.0(+0x25bc5) [0x286bc5]
/lib/libpthread.so.0(+0x5cc9) [0xb4ecc9]
/lib/libc.so.6(clone+0x5e) [0x35e6ae]
[Mon Apr 25 23:35:06 2011] [notice] child pid 1697 exit signal Trace/breakpoint trap (5)

Bah! This looks to be due to mod_spdy being dead code. The SPDY specification has progressed to draft 2, while mod_spdy has been stuck on the original draft since it was abandoned.

Bummer. Looks like I will get to code implementations sooner than expected. Tomorrow.

Day #1

My Chain #3

‹prev | My Chain | next›

It's time for a new chain.

Looking back, I think I enjoyed my first chain a bit more than the second. I got a bit side-tracked on the second one. Although I had a good time and learned a ton, I think I missed the drive and focus that can only come from a finish line.

So, for this, my third chain, I am going to mix things up again. This time around, I will produce an e-book in 3 months time. My initial plan:

• May 31—alpha version, available to limited, interested readers
• Jun 30—beta version, available for order
• Jul 31—final version

In a nutshell, I want to use my chain (blog post every night until I am done) to go from novitiate to subject matter expert—in 3 months.

Possible? I honestly do not know. But where's the fun in setting SMART goals? I love me some BHAGs.

Oh yeah, the subject of the book: SPDY.

Follow along!