goaway when talking to Cloudflare #129

ioquatix · 2018-05-03T11:15:36Z

When I tried to send the headers frame twice, I received goaway.

I ended up doing this:

			class Merged
				def initialize(*all)
					@all = all
				end
				
				def each(&block)
					@all.each do |headers|
						headers.each do |key, value|
							yield key, value.to_s
						end
					end
				end
			end

However, is there some reason why sending headers twice would be a problem? After my discussion with @HoneyryderChuck I thought it was ok (with end_headers:false).

The text was updated successfully, but these errors were encountered:

HoneyryderChuck · 2018-05-03T12:44:12Z

Could you print a "frame trace"? That's interesting indeed.

ioquatix · 2018-05-03T12:44:49Z

Let me see if I can repro... I sort of trashed all that code now.

ioquatix · 2018-05-03T13:07:09Z

Okay first problem. If headers is an empty hash, it fails:

     1.1) Failure/Error: stream.headers(headers.all[1], end_stream: true)
          
          NoMethodError:
            undefined method `force_encoding' for {}:Hash
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/buffer.rb:70:in `block (2 levels) in <class:Buffer>'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/framer.rb:203:in `generate'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/connection.rb:398:in `block in encode'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/connection.rb:398:in `map'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/connection.rb:398:in `encode'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/connection.rb:381:in `send'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/client.rb:38:in `send'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/emitter.rb:34:in `block in emit'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/emitter.rb:33:in `delete_if'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/emitter.rb:33:in `emit'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/stream.rb:141:in `block in send'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/stream.rb:608:in `manage_state'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/stream.rb:140:in `send'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/stream.rb:156:in `headers'
          # ./lib/async/http/protocol/http2.rb:255:in `call'
          # ./lib/async/http/client.rb:73:in `call'
          # ./lib/async/http/middleware.rb:28:in `block (2 levels) in <module:Verbs>'
          # ./spec/async/http/client_spec.rb:61:in `block (3 levels) in <top (required)>'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/async-rspec-1.5.0/lib/async/rspec/reactor.rb:55:in `block (2 levels) in run_example'
          # /Users/samuel/.rvm/gems/ruby-2.5.0/gems/async-1.8.0/lib/async/task.rb:74:in `block in initialize'

ioquatix · 2018-05-03T13:07:32Z

Uh, actually hold on, let me check that.

ioquatix · 2018-05-03T13:08:11Z

Yes,

stream.headers({}, end_stream: true)

fails.

ioquatix · 2018-05-03T13:09:31Z

Sending headers twice fails with:

D, [2018-05-04T01:09:00.374279 #81842] DEBUG -- #<Async::HTTP::Pool:0x00007f8ce584ecb0>: No available resources, allocating new one...
D, [2018-05-04T01:09:00.374341 #81842] DEBUG -- #<Async::HTTP::Client:0x00007f8ce584f4a8>: Making connection to #<Async::HTTP::URLEndpoint:0x00007f8ce583c588 @options={}, @url=#<URI::HTTPS https://www.codeotaku.com/>, @endpoint=nil>
D, [2018-05-04T01:09:00.380776 #81842] DEBUG -- #<Async::Debug::Selector:0x00007f8ce48356a8>: Registering #<Socket:fd 12> for w.
D, [2018-05-04T01:09:00.566894 #81842] DEBUG -- #<Async::Debug::Selector:0x00007f8ce48356a8>: Deregistering #<Socket:fd 12>.
D, [2018-05-04T01:09:00.567333 #81842] DEBUG -- #<Async::Debug::Selector:0x00007f8ce48356a8>: Registering #<OpenSSL::SSL::SSLSocket:0x00007f8ce580d2d8 @context=#<OpenSSL::SSL::SSLContext:0x00007f8ce580b730 @alpn_protocols=["h2", "http/1.1"], @max_proto_version=nil, @min_proto_version=769, @verify_mode=1, @verify_hostname=true, @cert_store=#<OpenSSL::X509::Store:0x00007f8ce68072d8 @verify_callback=nil, @error=nil, @error_string=nil, @chain=nil, @time=nil>>, @io=#<Socket:fd 12>, @eof=false, @rbuffer="", @sync=true, @sync_close=true, @hostname="www.codeotaku.com"> for r.
D, [2018-05-04T01:09:00.943102 #81842] DEBUG -- Async::HTTP::Protocol::HTTPS: Negotiating protocol "h2"...
D, [2018-05-04T01:09:00.943647 #81842] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: Sent frame: {:type=>:settings, :stream=>0, :payload=>[[:settings_max_concurrent_streams, 100]]}
D, [2018-05-04T01:09:00.943856 #81842] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: Sent frame: {:type=>:headers, :flags=>[], :payload=>{":scheme"=>"https", ":method"=>"GET", ":path"=>"/index", ":authority"=>"www.codeotaku.com"}, :stream=>1}
D, [2018-05-04T01:09:00.944293 #81842] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: Sent frame: {:type=>:headers, :flags=>[:end_headers, :end_stream], :payload=>{"foo"=>"bar"}, :stream=>1}
D, [2018-05-04T01:09:00.944899 #81842] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: Received frame: {:length=>18, :type=>:settings, :flags=>[], :stream=>0, :payload=>[[:settings_max_concurrent_streams, 128], [:settings_initial_window_size, 65536], [:settings_max_frame_size, 16777215]]}
/Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/connection.rb:586: warning: instance variable @h2c_upgrade not initialized
D, [2018-05-04T01:09:00.945023 #81842] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: Sent frame: {:type=>:settings, :stream=>0, :payload=>[], :flags=>[:ack]}
D, [2018-05-04T01:09:00.945231 #81842] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: Received frame: {:length=>4, :type=>:window_update, :flags=>[], :stream=>0, :increment=>2147418112}
D, [2018-05-04T01:09:00.945352 #81842] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: Stream flushed, waiting for signal.
D, [2018-05-04T01:09:01.129794 #81842] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: Received frame: {:length=>0, :type=>:settings, :flags=>[:ack], :stream=>0, :payload=>[]}
D, [2018-05-04T01:09:01.129981 #81842] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: Received frame: {:length=>4, :type=>:window_update, :flags=>[], :stream=>1, :increment=>2147418111}
D, [2018-05-04T01:09:01.130883 #81842] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: Received frame: {:length=>8, :type=>:goaway, :flags=>[], :stream=>0, :last_stream=>1, :error=>:protocol_error}
E, [2018-05-04T01:09:01.130956 #81842] ERROR -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: goaway: 1
D, [2018-05-04T01:09:01.131091 #81842] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007f8ce603fc58>: Connection reset by peer!
D, [2018-05-04T01:09:05.377488 #81842] DEBUG -- <Async::Reactor:0x3fc672401014 stopped=true>: Exiting run-loop because #<Async::TimeoutError: run time exceeded duration 5s:
<Async::Reactor:0x3fc672401014 stopped=false>
	<Async::Task:0x3fc672400560 RSpec::ExampleGroups::AsyncHTTPClient::AsyncHTTPProtocolHTTPS status=running>
		<Async::Task:0x3fc6724043cc timer task duration=5 status=running>
		<Async::Task:0x3fc672436b74 connected to #<Addrinfo: 192.81.135.133:443 TCP (www.codeotaku.com)> status=running>

HoneyryderChuck · 2018-05-03T13:16:13Z

That's indeed interesting. Let me have a look at it later. As a sidenote, is this an issue only with cloudflare endpoints? Or overall?

ioquatix · 2018-05-03T13:18:24Z

It worked with internal requests, i.e. async-http client and server seemed fine.

Here is a full transaction/example:

D, [2018-05-04T01:17:49.850114 #81906] DEBUG -- Async::IO::Socket: Binding to #<Addrinfo: 127.0.0.1:9294 TCP>
D, [2018-05-04T01:17:49.850419 #81906] DEBUG -- #<Async::Debug::Selector:0x00007fdd18806ab8>: Registering #<Socket:fd 10> for r.
D, [2018-05-04T01:17:49.850493 #81906] DEBUG -- #<Async::HTTP::Pool:0x00007fdd188977e8>: No available resources, allocating new one...
D, [2018-05-04T01:17:49.850544 #81906] DEBUG -- #<Async::HTTP::Client:0x00007fdd18885cc8>: Making connection to #<Async::HTTP::URLEndpoint:0x00007fdd18874798 @options={:reuse_port=>true}, @url=#<URI::HTTP http://127.0.0.1:9294/>, @endpoint=#<Async::IO::HostEndpoint:0x00007fdd188ddc98 @options={:reuse_port=>true}, @specification=["127.0.0.1", 9294, nil, 1]>>
D, [2018-05-04T01:17:49.850756 #81906] DEBUG -- #<Async::Debug::Selector:0x00007fdd18806ab8>: Registering #<Socket:fd 11> for w.
D, [2018-05-04T01:17:49.850988 #81906] DEBUG -- #<Async::HTTP::Server:0x00007fdd18886d58>: Incoming connnection from #<Addrinfo: 127.0.0.1:53426 TCP> to #<Async::HTTP::Protocol::HTTP2:0x00007fdd18956eb8>
D, [2018-05-04T01:17:49.851064 #81906] DEBUG -- #<Async::Debug::Selector:0x00007fdd18806ab8>: Registering #<Socket:fd 12> for r.
D, [2018-05-04T01:17:49.851273 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18997120>: Sent frame: {:type=>:settings, :stream=>0, :payload=>[[:settings_max_concurrent_streams, 100]]}
D, [2018-05-04T01:17:49.851362 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18997120>: Sent frame: {:type=>:headers, :flags=>[], :payload=>{":scheme"=>"https", ":method"=>"GET", ":path"=>"/", ":authority"=>"127.0.0.1"}, :stream=>1}
D, [2018-05-04T01:17:49.851569 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18997120>: Sent frame: {:type=>:headers, :flags=>[:end_headers, :end_stream], :payload=>{"foo"=>"bar"}, :stream=>1}
D, [2018-05-04T01:17:49.851788 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18997120>: Stream flushed, waiting for signal.
D, [2018-05-04T01:17:49.851879 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18956eb8>: Sent frame: {:type=>:settings, :stream=>0, :payload=>[[:settings_max_concurrent_streams, 100]]}
D, [2018-05-04T01:17:49.851989 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18956eb8>: Received frame: {:length=>6, :type=>:settings, :flags=>[], :stream=>0, :payload=>[[:settings_max_concurrent_streams, 100]]}
/Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/connection.rb:586: warning: instance variable @h2c_upgrade not initialized
D, [2018-05-04T01:17:49.852051 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18956eb8>: Sent frame: {:type=>:settings, :stream=>0, :payload=>[], :flags=>[:ack]}
D, [2018-05-04T01:17:49.852118 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18956eb8>: Received frame: {:length=>12, :type=>:headers, :flags=>[:end_headers], :stream=>1, :payload=>"\x87\x82\x84A\x87\b\x9D\\\v\x81p\xFF"}
D, [2018-05-04T01:17:49.852290 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18956eb8>: Received frame: {:length=>8, :type=>:headers, :flags=>[:end_stream, :end_headers], :stream=>1, :payload=>"@\x82\x94\xE7\x03bar"}
D, [2018-05-04T01:17:49.852375 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18956eb8>: Sent frame: {:type=>:headers, :flags=>[:end_headers, :end_stream], :payload=>{":status"=>"200"}, :stream=>1}
D, [2018-05-04T01:17:49.852561 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18997120>: Received frame: {:length=>6, :type=>:settings, :flags=>[], :stream=>0, :payload=>[[:settings_max_concurrent_streams, 100]]}
/Users/samuel/.rvm/gems/ruby-2.5.0/gems/http-2-0.9.0/lib/http/2/connection.rb:586: warning: instance variable @h2c_upgrade not initialized
D, [2018-05-04T01:17:49.852611 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18997120>: Sent frame: {:type=>:settings, :stream=>0, :payload=>[], :flags=>[:ack]}
D, [2018-05-04T01:17:49.852694 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18997120>: Received frame: {:length=>0, :type=>:settings, :flags=>[:ack], :stream=>0, :payload=>[]}
D, [2018-05-04T01:17:49.852737 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18997120>: Received frame: {:length=>1, :type=>:headers, :flags=>[:end_stream, :end_headers], :stream=>1, :payload=>"\x88"}
D, [2018-05-04T01:17:49.852843 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18997120>: Stream finished: #<struct Async::HTTP::Response version="HTTP/2.0", status=200, reason=nil, headers=#<Async::HTTP::Headers:0x00007fdd18994858 @fields=[], @indexed={}>, body=#<Async::HTTP::Body::Writable 0 chunks written>>
D, [2018-05-04T01:17:49.854078 #81906] DEBUG -- #<Async::Debug::Selector:0x00007fdd18806ab8>: Deregistering #<Socket:fd 12>.
D, [2018-05-04T01:17:49.854185 #81906] DEBUG -- #<Async::Debug::Selector:0x00007fdd18806ab8>: Deregistering #<Socket:fd 10>.
D, [2018-05-04T01:17:49.854311 #81906] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fdd18997120>: Closing connection
D, [2018-05-04T01:17:49.854382 #81906] DEBUG -- #<Async::Debug::Selector:0x00007fdd18806ab8>: Deregistering #<Socket:fd 11>.
D, [2018-05-04T01:17:49.854514 #81906] DEBUG -- <Async::Reactor:0x3fee8c407990 stopped=false>: Exiting run-loop because finished.

ioquatix · 2018-05-03T13:21:41Z

CloudFlare might just have a broken implementation of HTTP/2?

HoneyryderChuck · 2018-05-03T13:46:43Z

I'd assume the opposite. They see more daily usage than this lib. It's either misusage or a bug, most likely

HoneyryderChuck · 2018-05-04T16:37:00Z

could you share the URL you tested this against? I've tested this against google, and it worked.

HoneyryderChuck · 2018-05-04T16:38:29Z

ok, tested it against https://www.cloudflare.com, and reproduced your problem. It seems to be that their stack doesn't support CONTINUATION frames(?)

igrigorik · 2018-05-04T17:13:09Z

/cc @jgrahamc for tips and guidance from Cloudflare side :-)

ioquatix · 2018-06-06T22:48:23Z

Any update on this, or should we close as a bug with Cloudflare?

ioquatix · 2018-06-30T22:02:59Z

According to my understanding of the spec, sending multiple header frames is invalid. That being said, it should be possible to use it for trailing headers, but that's not something I tested.

ioquatix closed this as completed Jun 30, 2018

ioquatix mentioned this issue Jul 5, 2018

Add strict mode flag. #134

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

goaway when talking to Cloudflare #129

goaway when talking to Cloudflare #129

ioquatix commented May 3, 2018

HoneyryderChuck commented May 3, 2018

ioquatix commented May 3, 2018

ioquatix commented May 3, 2018

ioquatix commented May 3, 2018

ioquatix commented May 3, 2018 •

edited

Loading

ioquatix commented May 3, 2018 •

edited

Loading

HoneyryderChuck commented May 3, 2018

ioquatix commented May 3, 2018

ioquatix commented May 3, 2018

HoneyryderChuck commented May 3, 2018

HoneyryderChuck commented May 4, 2018

HoneyryderChuck commented May 4, 2018

igrigorik commented May 4, 2018

ioquatix commented Jun 6, 2018

ioquatix commented Jun 30, 2018

goaway when talking to Cloudflare #129

goaway when talking to Cloudflare #129

Comments

ioquatix commented May 3, 2018

HoneyryderChuck commented May 3, 2018

ioquatix commented May 3, 2018

ioquatix commented May 3, 2018

ioquatix commented May 3, 2018

ioquatix commented May 3, 2018 • edited Loading

ioquatix commented May 3, 2018 • edited Loading

HoneyryderChuck commented May 3, 2018

ioquatix commented May 3, 2018

ioquatix commented May 3, 2018

HoneyryderChuck commented May 3, 2018

HoneyryderChuck commented May 4, 2018

HoneyryderChuck commented May 4, 2018

igrigorik commented May 4, 2018

ioquatix commented Jun 6, 2018

ioquatix commented Jun 30, 2018

ioquatix commented May 3, 2018 •

edited

Loading

ioquatix commented May 3, 2018 •

edited

Loading