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