Tuesday, May 10, 2011

Ugly Zlib Errors Without Solutions

‹prev | My Chain | next›

Today I would like to see if I can get a grip on the zlib algorithm with respect to SPDY. Yesterday I found that my npn_spdy_server.rb eventmachine was crashing on receipt of a SYN_REPLY. The crash seemed to indicate the zlib decompresion as the culprit:
/home/chris/repos/spdy/lib/spdy/compressor.rb:35:in `inflate': invalid stream (RuntimeError)
from /home/chris/repos/spdy/lib/spdy/parser.rb:51:in `unpack_control'
from /home/chris/repos/spdy/lib/spdy/parser.rb:81:in `try_parse'
from /home/chris/repos/spdy/lib/spdy/parser.rb:19: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>'
Before wading too deep, I stick a print-stderr statement in parser just before line 19 where it is crashing:
    def <<(data)

$stderr.puts "data is: " + data.unpack('M*').pretty_inspect

@buffer << data
#...
Trying this again, I see that:
data is: ["\x80\x02\x00\x01\x01\x00\x01\"\x00\x00\x00\x01\x00\x00\x00\x00\x00\x008\xEA\xDF\xA2Q\xB2b\xE0a`\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"]

...

data is: ["\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("]
This says that both times that packets are being received by eventmachine, they are SYN_STREAMS (the fourth byte pair in both is \x01 => SYN_STREAM). It is the second one that is crashing, but let's make sure the first one works as expected.

Using the SPDY gem from an irb console:
ruby-1.9.2-p180 :001 > $: << 'lib' << '../lib'
ruby-1.9.2-p180 :002 > require 'spdy'
=> true
ruby-1.9.2-p180 :003 > ss = SPDY::Protocol::Control::SynStream.new
=> {"header"=>{"frame"=>1, "version"=>2, "type"=>0, "flags"=>0, "len"=>0, "stream_id"=>0}, "associated_to_stream_id"=>0, "pri"=>0, "data"=>""}
ruby-1.9.2-p180 :004 > ss.parse("\x80\x02\x00\x01\x01\x00\x01\"\x00\x00\x00\x01\x00\x00\x00\x00\x00\x008\xEA\xDF\xA2Q\xB2b\xE0a`\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")
IOError: data truncated
from /home/chris/.rvm/gems/ruby-1.9.2-p180@spdy/gems/bindata-1.3.1/lib/bindata/io.rb:88:in `readbytes'
from /home/chris/.rvm/gems/ruby-1.9.2-p180@spdy/gems/bindata-1.3.1/lib/bindata/string.rb:120:in `read_and_return_value'
from /home/chris/.rvm/gems/ruby-1.9.2-p180@spdy/gems/bindata-1.3.1/lib/bindata/base_primitive.rb:134:in `do_read'
from /home/chris/.rvm/gems/ruby-1.9.2-p180@spdy/gems/bindata-1.3.1/lib/bindata/struct.rb:223:in `block in do_read'
from /home/chris/.rvm/gems/ruby-1.9.2-p180@spdy/gems/bindata-1.3.1/lib/bindata/struct.rb:223:in `each'
from /home/chris/.rvm/gems/ruby-1.9.2-p180@spdy/gems/bindata-1.3.1/lib/bindata/struct.rb:223:in `do_read'
from /home/chris/.rvm/gems/ruby-1.9.2-p180@spdy/gems/bindata-1.3.1/lib/bindata/base.rb:150:in `read'
from /home/chris/repos/spdy/lib/spdy/protocol.rb:18:in `parse'
from (irb):4
from /home/chris/.rvm/rubies/ruby-1.9.2-p180/bin/irb:16:in `<main>'
Oh now, come on! That should work.

If I parse the packet in the RSpec help, it does work:
ruby-1.9.2-p180 :005 > ss = SPDY::Protocol::Control::SynStream.new
=> {"header"=>{"frame"=>1, "version"=>2, "type"=>0, "flags"=>0, "len"=>0, "stream_id"=>0}, "associated_to_stream_id"=>0, "pri"=>0, "data"=>""}
ruby-1.9.2-p180 :006 > ss.parse("\x80\x02\x00\x01\x01\x00\x01E\x00\x00\x00\x01\x00\x00\x00\x00\x00\x008\xEA\xDF\xA2Q\xB2b\xE0f`\x83\xA4\x17\x86(4\xDBu0\xAC\xD7\x06\x89\xC2\xFDa]hk\xA0g\xA9\x83p\x13X\xC0B\a\xEE?\x1D-}-\xB0\x98)\x03\x1Fjff\x90\xF3\f\xF6\x87:U\a\xECV\xB0:s\x1D\x88zc\x06~\xB4\xEC\xCE \b\xF2\x8C\x0E\xD47:\xC5)\xC9\x19p5\xB0\x14\xC2\xC0\x97\x9A\xA7\e\x1A\xAC\x93\nu\b\x03/J:d\xE0\x84\x86\x96\xAD\x01\x03\v\xA8``\xE0342\xD73\x00BC+K\x03\x03\x03\x06\xB6\\`\x81\x94\x9F\xC2\xC0\xEC\xEE\x1A\xC2\xC0V\f\xD4\x9B\x9B\xCA\xC0\x9AQRRP\xCC\xC0\f\n,\x11}{\x80\x80a\x9Do\x9B\xA8\x06,\x10\x80\xC5\x86mVq~\x1E\x03\x17\"\xD33\x94\xF9\xE6We\xE6\xE4$\xEA\x9B\xEA\x19(h\xF8&&g\xE6\x95\xE4\x17gX+x\x02\xD3a\x8E\x02P@\xC1?X!B\xC1\xD0 \xDE,\xDE\\S\xC1\x11\x18\xC4\xA9\xE1\xA9I\xDE\x99%\xFA\xA6\xC6&zF&\n\x1A\xDE\x1E!\xBE>:\n9\x99\xD9\xA9\n\xEE\xA9\xC9\xD9\xF9\x9A\n\xCE\x19\xC0\xC2,U\xDF\xD0\x10\xE8X3K3=#\v\x85\xE0\xC4\xB4\xC4\xA2L\xA8&\x06vh\x942p\xC0b\x1A\x00\x00\x00\xFF\xFF")
=> {"header"=>{"frame"=>1, "version"=>2, "type"=>1, "flags"=>1, "len"=>325, "stream_id"=>1}, "associated_to_stream_id"=>0, "pri"=>0, "data"=>"8\xEA\xDF\xA2Q\xB2b\xE0f`\x83\xA4\x17\x86(4\xDBu0\xAC\xD7\x06\x89\xC2\xFDa]hk\xA0g\xA9\x83p\x13X\xC0B\a\xEE?\x1D-}-\xB0\x98)\x03\x1Fjff\x90\xF3\f\xF6\x87:U\a\xECV\xB0:s\x1D\x88zc\x06~\xB4\xEC\xCE \b\xF2\x8C\x0E\xD47:\xC5)\xC9\x19p5\xB0\x14\xC2\xC0\x97\x9A\xA7\e\x1A\xAC\x93\nu\b\x03/J:d\xE0\x84\x86\x96\xAD\x01\x03\v\xA8``\xE0342\xD73\x00BC+K\x03\x03\x03\x06\xB6\\`\x81\x94\x9F\xC2\xC0\xEC\xEE\x1A\xC2\xC0V\f\xD4\x9B\x9B\xCA\xC0\x9AQRRP\xCC\xC0\f\n,\x11}{\x80\x80a\x9Do\x9B\xA8\x06,\x10\x80\xC5\x86mVq~\x1E\x03\x17\"\xD33\x94\xF9\xE6We\xE6\xE4$\xEA\x9B\xEA\x19(h\xF8&&g\xE6\x95\xE4\x17gX+x\x02\xD3a\x8E\x02P@\xC1?X!B\xC1\xD0 \xDE,\xDE\\S\xC1\x11\x18\xC4\xA9\xE1\xA9I\xDE\x99%\xFA\xA6\xC6&zF&\n\x1A\xDE\x1E!\xBE>:\n9\x99\xD9\xA9\n\xEE\xA9\xC9\xD9\xF9\x9A\n\xCE\x19\xC0\xC2,U\xDF\xD0\x10\xE8X3K3=#\v\x85\xE0\xC4\xB4\xC4\xA2L\xA8&\x06vh\x942p\xC0b\x1A\x00\x00\x00\xFF\xFF"}
Ugh. There is all sorts of wrong going on here. It seems that either (a) the current implementation of the SPDY gem is not parsing valid, real world packets or (b) I am not seeing all of the real world packet. I table that question for now, most likely for another day.

The more immediate question is why does the first real world packet not crash things? SynStream is not able to parse it any more than it can the second SYN_STREAM packet that does crash things. What gives?

Looking through the parser code, I see that we are not SynStream#parse-ing, but SynStream#read-ing:
      def unpack_control(pckt, data)
pckt.read(data)
...
That packet is then Zlib.inflated:
        if pckt.data.size > 0
data = Zlib.inflate(pckt.data.to_s)
headers = NV.new.read(data).to_h
end
Trying this out in the console, the data section from the first packet does indeed decompress:
ruby-1.9.2-p180 :012 >   SPDY::Zlib.inflate "8\xEA\xDF\xA2Q\xB2b\xE0a`\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"
=> "\x00\f\x00\x06accept\x00?text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\x00\x0Eaccept-charset\x00\x1EISOon/xhtm"
But, the data from the second pack does crash:
ruby-1.9.2-p180 :013 > SPDY::Zlib.inflate "b\xE0\x82\xC7\x1630\xDC\a&\xC4\x89\nX,\xC1\xC8\xA3\x9F\x96X\x96\t\x8C("
RuntimeError: invalid stream
from /home/chris/repos/spdy/lib/spdy/compressor.rb:35:in `inflate'
from (irb):13
from /home/chris/.rvm/rubies/ruby-1.9.2-p180/bin/irb:16:in `<main>'
Ah, unlucky 13.

Just for the heck of it, I retry my irb session from scratch...still no joy:
ruby-1.9.2-p180 :001 > $: << 'lib' << '../lib' 
ruby-1.9.2-p180 :002 > require 'spdy'
=> true
ruby-1.9.2-p180 :003 > SPDY::Zlib.inflate "b\xE0\x82\xC7\x1630\xDC\a&\xC4\x89\nX,\xC1\xC8\xA3\x9F\x96X\x96\t\x8C("
RuntimeError: invalid stream
from /home/chris/repos/spdy/lib/spdy/compressor.rb:35:in `inflate'
from (irb):3
from /home/chris/.rvm/rubies/ruby-1.9.2-p180/bin/irb:16:in `<main>'
So either the packet is wrong or the Zlib implementation is wrong.

Sigh. Looks like I will be picking back up trying to read / decompress this packet:
"\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("
And this data section:
"b\xE0\x82\xC7\x1630\xDC\a&\xC4\x89\nX,\xC1\xC8\xA3\x9F\x96X\x96\t\x8C("
Ugh.


Day #16

1 comment:

  1. My speculation about needing to keep your zlib state between the first and second responses is confirmed by the following text from the SPDY spec: "The entire contents of the name/value header block is compressed using zlib deflate. There is a single zlib stream (context) for all name value pairs in one direction on a connection. SPDY uses a SYNC_FLUSH between frame which uses compression."

    ReplyDelete