Failing client requests #122

ioquatix · 2018-03-20T04:22:04Z

I'm using the latest published gem (0.9.0).

I'm working on an asynchronous implementation which has feature parity with HTTP1 (connection per request and sequential connections using keep-alive). I'm working on the HTTP2 implementation which for the most part appears to work except the functionality depends on when I start the read loop.

Here are two dumps from my client:

Sent frame: {:type=>:settings, :stream=>0, :payload=>[[:settings_max_concurrent_streams, 100]]}
Sent frame: {:type=>:headers, :flags=>[:end_headers, :end_stream], :payload=>{":method"=>"GET", ":path"=>"/", ":scheme"=>"https", ":authority"=>"www.codeotaku.com", "accept"=>"*/*", "user-agent"=>"nghttp2/1.30.0"}, :stream=>1}

-- start read loop here

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]]}
Sent frame: {:type=>:settings, :stream=>0, :payload=>[], :flags=>[:ack]}
Received frame: {:length=>4, :type=>:window_update, :flags=>[], :stream=>0, :increment=>2147418112}
Received frame: {:length=>0, :type=>:settings, :flags=>[:ack], :stream=>0, :payload=>[]}

Received frame: {:length=>160, :type=>:headers, :flags=>[:end_headers], :stream=>1, :payload=>"H\x03301\\\x010\x00\x84BF\x9BQ\x90d\x01SA\xFB\x96E5\x96\xCAGQjM\x1E\xBF\x00\x86\xA0\xE4\x1ALz\xBF\x85`\xD5H_?\x00\x89 \xC99V!\xEAM\x87\xA3\x8A\xA4~V\x1C\xC5\x81\xE7\x1A\x00?\x00\x83\x90i/\x96\xDFi~\x94\x10\x14\xD0;\x14\x10\x02\xF2\x80f\xE3-\xDCi\xE51h\xDF\x00\x89\xF2\xB5g\xF0[\v\"\xD1\xFA\x91\xD7=\xA81\xEASX\xD0\x82\xD51lQ\xB5\xC2\xB8\x7F\x00\x85Al\xEE[?\x9C\xAAcU\xE5\x80\xAE\x10\xAE\xFA\x9F\xEDMs\xDA\x83\x1E\xA55\x8D\b-S\x16\xC5\e\\+\x87"}
Received frame: {:length=>0, :type=>:data, :flags=>[:end_stream], :stream=>1, :payload=>""}

It appears that depending on when the read loop is started (i.e. before new_stream or after) changes the behaviour of the client connection, and in this case it fails:

-- start read loop here

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]]}
Sent frame: {:type=>:settings, :stream=>0, :payload=>[], :flags=>[:ack]}
Received frame: {:length=>4, :type=>:window_update, :flags=>[], :stream=>0, :increment=>2147418112}
Sent frame: {:type=>:headers, :flags=>[:end_headers, :end_stream], :payload=>{":scheme"=>"https", ":method"=>"GET", ":path"=>"/", ":authority"=>"www.codeotaku.com", "accept"=>"*/*", "user-agent"=>"spider"}, :stream=>1}
Received frame: {:length=>8, :type=>:goaway, :flags=>[], :stream=>0, :last_stream=>0, :error=>:protocol_error}

I'm not absolutely certain what the issue is yet but I thought I'd report my initial findings. I'll follow up with more details as they become available.

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

HoneyryderChuck · 2018-03-20T08:22:32Z

I had some issues with this before, it might mean that the headers frame was crafted before the handshake was performed and might be in an invalid state, but hard to say without a small repro code.

On another note, I've created this gem, which aims at supporting HTTP/2 and HTTP/1 and multiple concurrent requests, if you want to have a look. Maybe it solves your problem already.

ioquatix · 2018-03-20T08:35:37Z

I have a repro care to take a look at it with me?

ioquatix · 2018-03-20T08:42:45Z

@HoneyryderChuck Are you able to join https://gitter.im/socketry/async to discuss?

ioquatix · 2018-03-20T08:45:35Z

Here is the repro

git clone [email protected]:socketry/async-http
cd async-http
bundle install
rspec

  Async::HTTP::Protocol::HTTPS
D, [2018-03-20T21:44:47.521268 #79926] DEBUG -- #<Async::HTTP::Pool:0x00007fc15406ccb0>: No available resources, allocating new one...
D, [2018-03-20T21:44:47.521333 #79926] DEBUG -- Async::HTTP::Protocol::HTTPS: Making connection to #<struct Async::HTTP::URLEndpoint specification=#<URI::HTTPS https://www.codeotaku.com>, options={}>
D, [2018-03-20T21:44:47.521366 #79926] DEBUG -- #<struct Async::HTTP::URLEndpoint specification=#<URI::HTTPS https://www.codeotaku.com>, options={}>: Setting hostname: www.codeotaku.com
D, [2018-03-20T21:44:48.375314 #79926] DEBUG -- Async::HTTP::Protocol::HTTPS: Negotiating protocol "h2"...
D, [2018-03-20T21:44:48.375567 #79926] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fc154348c90>: 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]]}
D, [2018-03-20T21:44:48.375618 #79926] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fc154348c90>: Sent frame: {:type=>:settings, :stream=>0, :payload=>[], :flags=>[:ack]}
D, [2018-03-20T21:44:48.375737 #79926] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fc154348c90>: Received frame: {:length=>4, :type=>:window_update, :flags=>[], :stream=>0, :increment=>2147418112}
D, [2018-03-20T21:44:48.375851 #79926] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fc154348c90>: Sent frame: {:type=>:headers, :flags=>[:end_headers, :end_stream], :payload=>{":scheme"=>"https", ":method"=>"GET", ":path"=>"/index", ":authority"=>"www.codeotaku.com"}, :stream=>1}
D, [2018-03-20T21:44:48.376113 #79926] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fc154348c90>: Stream flushed, waiting for signal.
D, [2018-03-20T21:44:48.789430 #79926] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fc154348c90>: Received frame: {:length=>8, :type=>:goaway, :flags=>[], :stream=>0, :last_stream=>0, :error=>:protocol_error}
D, [2018-03-20T21:44:48.789944 #79926] DEBUG -- #<Async::HTTP::Protocol::HTTP2:0x00007fc154348c90>: Connection reset by peer!

ioquatix · 2018-03-20T08:50:20Z

I'm testing using nghttp:

koyoko% nghttp -v --no-dep https://www.codeotaku.com
[  0.193] Connected
The negotiated protocol: h2
[  0.567] recv SETTINGS frame <length=18, flags=0x00, stream_id=0>
          (niv=3)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):128]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65536]
          [SETTINGS_MAX_FRAME_SIZE(0x05):16777215]
[  0.567] recv WINDOW_UPDATE frame <length=4, flags=0x00, stream_id=0>
          (window_size_increment=2147418112)
[  0.567] send SETTINGS frame <length=12, flags=0x00, stream_id=0>
          (niv=2)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65535]
[  0.567] send SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.567] send HEADERS frame <length=36, flags=0x05, stream_id=1>
          ; END_STREAM | END_HEADERS
          (padlen=0)
          ; Open new stream
          :method: GET
          :path: /
          :scheme: https
          :authority: www.codeotaku.com
          accept: */*
          accept-encoding: gzip, deflate
          user-agent: nghttp2/1.30.0
[  0.753] recv SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.754] recv (stream_id=1) :status: 301
[  0.754] recv (stream_id=1) content-length: 0
[  0.754] recv (stream_id=1) status: 301 Moved Permanently
[  0.754] recv (stream_id=1) location: /index
[  0.754] recv (stream_id=1) cache-control: max-age=86400
[  0.754] recv (stream_id=1) date: Tue, 20 Mar 2018 08:50:51 GMT
[  0.754] recv (stream_id=1) x-powered-by: Phusion Passenger 5.1.1
[  0.754] recv (stream_id=1) server: nginx/1.11.9 + Phusion Passenger 5.1.1
[  0.754] recv HEADERS frame <length=160, flags=0x04, stream_id=1>
          ; END_HEADERS
          (padlen=0)
          ; First response header
[  0.754] recv DATA frame <length=0, flags=0x01, stream_id=1>
          ; END_STREAM
[  0.754] send GOAWAY frame <length=8, flags=0x00, stream_id=0>
          (last_stream_id=0, error_code=NO_ERROR(0x00), opaque_data(0)=[])

It seems the only difference is in the broken case, don't send settings frame like so:

[  0.567] send SETTINGS frame <length=12, flags=0x00, stream_id=0>
          (niv=2)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65535]

ioquatix · 2018-03-20T08:58:01Z

Hmmm....

A SETTINGS frame MUST be sent by both endpoints at the start of a connection and MAY be sent at any other time by either endpoint over the lifetime of the connection. Implementations MUST support all of the parameters defined by this specification.

https://http2.github.io/http2-spec/#SETTINGS

So, it seems like a bug?

HoneyryderChuck · 2018-03-20T09:54:50Z

Here is the repro

I'll only be able to look into it later in the day, however, don't you have a small script that fits in a comment? Would greatly reduce the overhead of building a full project.

So, it seems like a bug?

Looking at your example and nghttp's, nghttp receives and processes the sender settings before sending their own. http-2 crafts the settings frame and buffers it first, but none of them are wrong spec-wise (it is the first frame being sent in both cases). You'd have to see internally why the protocol error is being thrown. You could also try the examples script in order to reproduce it (if that script fails, it is definitely a bug).

I'd suggest you give httpx a try though. I've been using it to test a ruby server implementation, and you might not need the low-level details of HTTP/2 frames. But if you really must, I'll see if I can have a look at it later.

ioquatix · 2018-03-20T09:57:22Z

@HoneyryderChuck Take a look at those examples again.

nghttp generates the following settings frame:

[  0.567] send SETTINGS frame <length=12, flags=0x00, stream_id=0>
          (niv=2)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65535]

Such a frame is never generated by http-2. It does generate a settings ACK, but it doesn't sent it's own SETTINGS frame which is required by the standard before sending the HEADERS frame.

ioquatix · 2018-03-20T09:58:18Z

I suspect what is happening is that the SETTINGS ACK is masking the generation of a proper settings frame, there is a pseudo-race condition in the logic of http-2, I'll see if I can make a PR.

HoneyryderChuck · 2018-03-20T10:05:09Z

Again, I'd have to see that small repro script. I see two different dumps from your example, One sending two frames before the read loop, and and the second one without those. Did you omit those two frames from the second dump, or are they really not being generated?

The second example might mean that you're reading frames from the socket and sending them to the connection before initializing your own. This gem expects you to initialize the request before exchanging frames. So, if you are not building frames from your request before exchanging, you should consider initializing it yourself

HoneyryderChuck · 2018-03-20T10:53:46Z

meaning:

connection = HTTP2::Client.new
# set up all your callbacks here
connection.send_connection_preface

ioquatix · 2018-03-20T11:33:31Z

Again, I'd have to see that small repro script. I see two different dumps from your example, One sending two frames before the read loop, and and the second one without those. Did you omit those two frames from the second dump, or are they really not being generated?

The initial settings frame is not being generated.

The second example might mean that you're reading frames from the socket and sending them to the connection before initializing your own. This gem expects you to initialize the request before exchanging frames. So, if you are not building frames from your request before exchanging, you should consider initializing it yourself

I will investigate this, but my usage is very similar to the README.

ioquatix · 2018-03-20T11:41:04Z

I see there is some kind of state management bug.

Here, it has a state transition from waiting_connection_preface to connected.

http-2/lib/http/2/client.rb

Lines 50 to 51 in 16dec9f

    
           return unless @state == :waiting_connection_preface 
        
           @state = :connected

But this transition can also be made here:

http-2/lib/http/2/connection.rb

Line 424 in 16dec9f

@state = :connected

So it seems that depending on the order of operations, part of the connection is not initialised.

HoneyryderChuck · 2018-03-20T11:44:27Z

If you followed the README example, there's your issue (@igrigorik , maybe consider changing it?). You should instead follow the example get, or as a quick fix, apply the thing I suggested in my last comment.

ioquatix · 2018-03-20T11:48:28Z

Okay, so adding a call to send_connection_preface fixed the issue. Is this by design?

ioquatix · 2018-03-20T11:53:29Z

@HoneyryderChuck Thanks so much for your help you've been awesome and patient :)

HoneyryderChuck · 2018-03-20T12:00:42Z

No worries :) .

It's kind of by design. Most of the examples here craft the frames from the client fully before doing network stuff (nghttp works the other way round, I suppose). This gem also doesn't control what you do regarding network, so all bets are off there. A higher level abstraction is also better, which is why I created httpx.

ioquatix · 2018-03-20T12:01:44Z

Fair enough, it still seems like a race condition in the state machine.

HoneyryderChuck · 2018-03-20T12:30:42Z

It's not a race condition, it's just an unhandled state transition.

A connection implements #send and #receive. For the client, the #send is patched so that the connection gets properly initialized. If you'd apply the same patch to #receive, it would solve the problem with your use case.

However, I assume that it would have some impact in the tests, so I'll defer to @igrigorik on whether this can/should be done.

ioquatix · 2018-03-20T22:07:54Z

Fair enough.

The way it's patched in the Client is a bit of a hack IMHO.

The problem is the object is not fully constructed after calling Client#initialize because you have to then set up the appropriate event callbacks. So, it's not possible to call send_connection_preface in the constructor.

@client = ::HTTP::Client.new

@client.on(:frame) { ... }

@client.send_connection_preface

What about

@client = ::HTTP::Client.new do |client|
    client.on(:frame) { ... }
end

At least this way it's possible to fully construct the object and make sure it's in a valid state.

ioquatix · 2018-03-20T22:09:48Z

You could even make a dedicated method if you don't want to change the API, e.g. Client.open do ... end

HoneyryderChuck · 2018-03-21T00:21:33Z

I'm not the best person to answer this, as this was @igrigorik design. But I don't find it bad, and one doesn't need to provide n ways to do the same if there is no tangible advantage. And this is supposed to be a lower level lib, not exactly user facing, so DSL ergonomics count less.

ioquatix · 2018-03-21T00:45:01Z

Those are all good points and mostly subjective.

Some objective ones: it's not documented clearly; should be in the constructor documentation I think, and perhaps in the README.

There are performance implications regarding latency and doing unnecessary work on the critical path. However, it's Ruby so ¯\_(ツ)_/¯.

Thanks for your continued input.

igrigorik · 2018-03-27T04:03:40Z

Hey guys, trying to catch up here.. apologies ahead of time if I'm rehashing what you already covered. I'm still a little puzzled as to what the bug is here:

https://github.com/igrigorik/http-2/blob/master/spec/client_spec.rb#L15-L22: tests for client emitting preface.
- send_connection_preface is an internal method, I don't think we should (or want) have upstream implementers calling it directly.
Client#send should emit connection_preface if one has not been sent yet
- https://github.com/igrigorik/http-2/blob/master/lib/http/2/client.rb#L37

What's missing in above? Can we write a failing spec test for this?

ioquatix · 2018-03-27T05:17:41Z

If you call Client#<< first, the state changes in a wonky way which means that the settings frame is never sent.

igrigorik · 2018-03-27T06:07:31Z

Ahh.. Ok, that's an oversight — let's fix that. To start, would you be willing to put together a failing spec? :)

ioquatix · 2018-03-27T06:45:57Z

Sure.

HoneyryderChuck · 2018-03-27T15:16:45Z

send_connection_preface is an internal method, I don't think we should (or want) have upstream implementers calling it directly.

Then part of the associated PR will have to make it a private method (I thought that this was public API and have advised @ioquatix in this regard).

ioquatix · 2018-04-12T22:40:09Z

#44 discusses the same problem.

ioquatix · 2018-06-30T22:06:13Z

I've worked around this issue. I may supply a PR to rework how send_connection_preface works.

Recently I've added a PR which specs the behaviour as it stands, so I'm happy with that.

ioquatix closed this as completed Mar 20, 2018

igrigorik reopened this Mar 27, 2018

ioquatix mentioned this issue Apr 16, 2018

Fix client when it initially receives data rather than sending it #126

Closed

ioquatix mentioned this issue Jun 23, 2018

[client] Be sure to send the preface if receiving data first. #44

Closed

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

Failing client requests #122

Failing client requests #122

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018 •

edited

Loading

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018 •

edited

Loading

HoneyryderChuck commented Mar 21, 2018

ioquatix commented Mar 21, 2018 •

edited

Loading

igrigorik commented Mar 27, 2018

ioquatix commented Mar 27, 2018 •

edited

Loading

igrigorik commented Mar 27, 2018

ioquatix commented Mar 27, 2018

HoneyryderChuck commented Mar 27, 2018

ioquatix commented Apr 12, 2018

ioquatix commented Jun 30, 2018

Failing client requests #122

Failing client requests #122

Comments

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018 • edited Loading

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

ioquatix commented Mar 20, 2018

HoneyryderChuck commented Mar 20, 2018

ioquatix commented Mar 20, 2018

ioquatix commented Mar 20, 2018 • edited Loading

HoneyryderChuck commented Mar 21, 2018

ioquatix commented Mar 21, 2018 • edited Loading

igrigorik commented Mar 27, 2018

ioquatix commented Mar 27, 2018 • edited Loading

igrigorik commented Mar 27, 2018

ioquatix commented Mar 27, 2018

HoneyryderChuck commented Mar 27, 2018

ioquatix commented Apr 12, 2018

ioquatix commented Jun 30, 2018

HoneyryderChuck commented Mar 20, 2018 •

edited

Loading

ioquatix commented Mar 20, 2018 •

edited

Loading

ioquatix commented Mar 21, 2018 •

edited

Loading

ioquatix commented Mar 27, 2018 •

edited

Loading