Debugging SPDY

‹prev | My Chain | next›

With the SPDY gem mostly complete, but for some minor refactoring, I focus my attention on a nagging problem. Whenever I access the example servers via SPDY, I get a crash:

chris@chris-VirtualBox:~/repos/spdy/examples$ 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", "cache-control"=>"no-cache", "host"=>"localhost:10000", "method"=>"GET", "pragma"=>"no-cache", "scheme"=>"https", "url"=>"/", "user-agent"=>"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.30 (KHTML, like Gecko) Chrome/12.0.742.30 Safari/534.30", "version"=>"HTTP/1.1"}]
[:SPDY, :sent, :SYN_REPLY]
[:SPDY, :sent, :DATA]
[:SPDY, :sent, :DATA_FIN]
[:SPDY, :connection_closed]
/home/chris/repos/spdy/lib/spdy/compressor.rb:35:in `inflate': invalid stream (RuntimeError)
        from /home/chris/repos/spdy/lib/spdy/parser.rb:33:in `unpack_control'
        from /home/chris/repos/spdy/lib/spdy/parser.rb:57:in `try_parse'
        from /home/chris/repos/spdy/lib/spdy/parser.rb:11:in `<<'
        from npn_spdy_server.rb:47:in `receive_data'
        from /home/chris/.rvm/gems/ruby-1.9.2-p180@spdy/gems/eventmachine-1.0.0.beta.3/lib/eventmachine.rb:206:in `run_machine'
        from /home/chris/.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>'

To try to figure this out, I first look in the about:net-internals of Chrome:



After clicking on the "Events" tab, set the filter to "type:SPDY_SESSION" (removing "is:active").

In both, I see DATA and DATA_FIN:

(P) t=1304990559507 [st= 13]     SPDY_SESSION_RECV_DATA  
                                 --> flags = 0
                                 --> size = 13
                                 --> stream_id = 1
(P) t=1304990559507 [st= 13]     SPDY_SESSION_RECV_DATA  
                                 --> flags = 0
                                 --> size = 0
                                 --> stream_id = 1

The next thing I see in the backend is the stack trace, but Chrome thinks that it is sending:

(P) t=1304990559725 [st=231]     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
                                     host: localhost:10000
                                     method: GET
                                     scheme: https
                                     url: /favicon.ico
                                     user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.30 (KHTML, like Gecko) Chrome/12.0.742.30 Safari/534.30
                                     version: HTTP/1.1
                                 --> id = 3

So Chrome is sending a SYN_STREAM to eventmachine. Given that npn_spdy_server.rb is crashing in the following:

              when 1 then # SYN_STREAM
                pckt = Control::SynStream.new
                unpack_control(pckt, @buffer)

...it seems that the backend is aware that it has received a SYN_STREAM, but is unable to parse the packet. Odd since it was able to parse the initial SYN_STREAM packet.

To debug this, I $stderr.puts the quoted-printable version of the string:

require 'pp'
$stderr.puts @buffer.unpack('M*').pretty_inspect

...and see:

["\x80\x02\x00\x01\x01\x00\x00.\x00\x00\x00\x03\x00\x00\x00\x00\x80\x00b\xE0\x82\xC7\x1630\xDC\a&\xC4\x89\nX,\xC1\xC8\xA3\x9F\x96X\x96\t\x8C("]

At this point I can read that: "\x80" means the control bit is set (properly), "\x02" means that we have gotten SPDY version 2 packet (properly), and "\x00\x02" means that this is a SYN_STREAM. The period in there represents decimal 46, which is the length of the name/value data.

Unfortunately, that all looks good to me. Further investigation points to this zlib code:

      result = FFI::Zlib.inflateInit(zstream)
      raise "invalid stream" if result != FFI::Zlib::Z_OK

      result = FFI::Zlib.inflate(zstream, FFI::Zlib::Z_SYNC_FLUSH)
      raise "invalid stream" if result != FFI::Zlib::Z_NEED_DICT

Ugh. I haven't the foggiest idea why zlib should normally want a dictionary, let alone why it does not want one in this case.

I will need to call it a night at this point, but I will pick back up trying to understand Zlib as it relates to NV frames in SPDY tomorrow.


Day #15