Monday, May 9, 2011

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

1 comment: