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