Update core + example server/client to pass h2spec

[igrigorik]

trafficstars

Instructions to build and run: https://github.com/summerwind/h2spec

Running ./h2spec -p 8080 against our example/server.rb yield lots bunch of failures:

• example server aborts the connection instead of sending GOAWAY / PROTOCOL_ERROR in bunch of places
• we don't enforce/emit FRAME_SIZE_ERROR
• ...

In short, lots of opportunities to improve error feedback!

[georgeu2000]

h2spec doesn't even run against insecure server for me(see below).

However, it does run (./bin/h2spec -p 8080 -t -k) against the secure server with 73 tests, 33 passed, 0 skipped, 40 failed.

I'll look into it...

go-workspace> ./bin/h2spec -p 8080
  3.5. HTTP/2 Connection Preface
    ✓ Sends invalid connection preface

  4.2. Frame Size
      Sends large size frame that exceeds the SETTINGS_MAX_FRAME_SIZE

ERROR: HTTP/2 `

HTTP2::Error::HandshakeError exception: HTTP2::Error::HandshakeError - closing socket.
    /Users/george/repos/http-2/lib/http/2/connection.rb:192:in `receive'
    example/server.rb:134:in `block in <main>'
    example/server.rb:46:in `loop'
    example/server.rb:46:in `<main>'

EDIT: Upon examination, the above error is coming from the first spec (which passes). h2spec stops running because of the settings negotiation timeout. Spec should fail and continue but that seems to be an issue with h2spec, and won't worry about it for now...

The issue is that http-2 server is not responding for some reason...

[igrigorik]

@georgeu2000 guessing, our demo server keels over and stops accepting connections..

[georgeu2000]

@igrigorik - I think what is happening is that we are receiving a frame of length 0:

Received bytes: 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a000000040000000000
Received frame: {:length=>0, :type=>:settings, :flags=>[], :stream=>0, :payload=>[]}

Which is strange because the spec is

4.2. Frame Size
  Sends large size frame that exceeds the SETTINGS_MAX_FRAME_SIZE

The buffer length is 0 and Framer is returning nil (Framer):

# Decodes complete HTTP/2 frame from provided buffer. If the buffer
# does not contain enough data, no further work is performed.
#
# @param buf [Buffer]
def parse(buf)
  return nil if buf.size < 9

However the connection is waiting for a frame (Connection):

  while (frame = @framer.parse(@recv_buffer))

So there is no response. Not sure what the desired functionality is yet, but perhaps it should emit a Settings frame...?

EDIT: Perhaps the decoder is not expecting the "large size frame" and it is overwriting another part of the message....

EDIT #2: After more digging, it turns out that many specs fail except for HTTP/2 Connection Preface. It has nothing to do with the Frame Size. There is an issue negotiating the connection or settings. This only happens with the insecure server.

[igrigorik]

EDIT #2: After more digging, it turns out that many specs fail except for HTTP/2 Connection Preface. It has nothing to do with the Frame Size. There is an issue negotiating the connection or settings. This only happens with the insecure server.

Ah, interesting. Are we not consuming some bytes, or some such? Thanks for digging into this!

[georgeu2000]

Not sure...but wondering why it only happens with the insecure server.

It strange because the only difference between them is that insecure server is a TCPServer and secure server is a OpenSSL::SSL::SSLServer.

Perhaps there is a difference in the the server.accept, sock.closed?, sock.eof? or sock.readpartial methods.

[georgeu2000]

This issue does not seem to have to do with the server or the socket, but with the settings negotiation.

The secure server sends the ack, and then receives an ack:

SECURE Server:

New TCP connection!
OpenSSL::SSL::SSLSocket
Received bytes: 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a
HTTP2::Server receive
--data: PRI * HTTP/2.0

SM

--
--@recv_buffer: ""--
Sent frame: {:type=>:settings, :stream=>0, :payload=>[[:settings_max_concurrent_streams, 100]]}
HTTP2::Framer parse
  buf: ""
Received bytes: 000000040000000000
HTTP2::Server receive
--data: --
--@recv_buffer: ""--
HTTP2::Framer parse
  buf: "\x00\x00\x00\x04\x00\x00\x00\x00\x00"
  frame:{:length=>0, :type=>:settings, :flags=>[], :stream=>0}
  payload: ""
HTTP2::Server receive [email protected](@recv_buffer)
  @recv_buffer: ""
  frame: {:length=>0, :type=>:settings, :flags=>[], :stream=>0, :payload=>[]}
Received frame: {:length=>0, :type=>:settings, :flags=>[], :stream=>0, :payload=>[]}
Sent frame: {:type=>:settings, :stream=>0, :payload=>[], :flags=>[:ack]}
HTTP2::Framer parse
  buf: ""
Received bytes: 000000040100000000
HTTP2::Server receive
--data: --
--@recv_buffer: ""--
HTTP2::Framer parse
  buf: "\x00\x00\x00\x04\x01\x00\x00\x00\x00"
  frame:{:length=>0, :type=>:settings, :flags=>[:ack], :stream=>0}
  payload: ""
HTTP2::Server receive [email protected](@recv_buffer)
  @recv_buffer: ""
  frame: {:length=>0, :type=>:settings, :flags=>[:ack], :stream=>0, :payload=>[]}
Received frame: {:length=>0, :type=>:settings, :flags=>[:ack], :stream=>0, :payload=>[]}

The non-secure server sends the ack, but never receives an ack. This is where the negotiation stops.

New TCP connection!
TCPSocket
Received bytes: 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a000000040000000000
HTTP2::Server receive
--data: PRI * HTTP/2.0

SM

--
--@recv_buffer: ""--
Sent frame: {:type=>:settings, :stream=>0, :payload=>[[:settings_max_concurrent_streams, 100]]}
HTTP2::Framer parse
  buf: "\x00\x00\x00\x04\x00\x00\x00\x00\x00"
  frame:{:length=>0, :type=>:settings, :flags=>[], :stream=>0}
  payload: ""
HTTP2::Server receive [email protected](@recv_buffer)
  @recv_buffer: ""
  frame: {:length=>0, :type=>:settings, :flags=>[], :stream=>0, :payload=>[]}
Received frame: {:length=>0, :type=>:settings, :flags=>[], :stream=>0, :payload=>[]}
Sent frame: {:type=>:settings, :stream=>0, :payload=>[], :flags=>[:ack]}
HTTP2::Framer parse
  buf: ""
<END>

Apparently the client is waiting for another message, but not sure what it is ATM. It seems that this message is not required for secure connection, or there is some other difference in the negotiation.

[georgeu2000]

OK, so finally figured out what is happening.

sock.write bytes (server.rb) does not seem to write anything to the socket. That is why the settings negotiation is timing out.

Replacing with sock.send bytes, 0 fixes the issue:

6.2. HEADERS
    × Sends a HEADERS frame followed by any frame other than CONTINUATION
      - The endpoint MUST treat the receipt of any other type of frame as a connection error of type PROTOCOL_ERROR.
        Expected: GOAWAY frame (ErrorCode: PROTOCOL_ERROR)
                  Connection close
          Actual: Test timeout
    × Sends a HEADERS frame followed by a frame on a different stream
      - The endpoint MUST treat the receipt of a frame on a different stream as a connection error of type PROTOCOL_ERROR.
        Expected: GOAWAY frame (ErrorCode: PROTOCOL_ERROR)
                  Connection close
          Actual: Test timeout
    ✓ Sends a HEADERS frame with 0x0 stream identifier
    ✓ Sends a HEADERS frame with invalid pad length

73 tests, 2 passed, 69 skipped, 2 failed

[georgeu2000]

Now the Non-Secure server can run the specs:

73 tests, 44 passed, 0 skipped, 29 failed

Secure server results:

73 tests, 33 passed, 0 skipped, 40 failed

[georgeu2000]

Since we seem to be coupling h2spec with http-2, we may want to update the tests to run against h2spec as well as the existing specs...?

Also update CI...

[igrigorik]

Since we seem to be coupling h2spec with http-2, we may want to update the tests to run against h2spec as well as the existing specs...?

I'd love to see h2spec integrated into our CI build.

[georgeu2000]

OK. What is the desired functionality?

Here's my suggestion. Output from h2spec is around 1,000 lines. So we can reduce to summary and failures in this format:

h2spec results:
73 tests, 30 passed, 0 skipped, 43 failed
  4.3. Header Compression and Decompression
    × Encodes Dynamic Table Size Update (RFC 7541, 6.3) after common header fields

This summary could be added as a comment in the PR (if that is possible). Not sure where else it could go.

Since we have so many failures, builds would pass even with h2spec failures.

[igrigorik]

If we want to force ourselves to pay attention to these test, and make sure we don't regress, then we have to get them running via Travis on each check-in.. The fact that we're currently red on many of them is a separate issue.

[georgeu2000]

I have gotten them running on Travis. Not sure where the output should go. Should Travis create a comment on each PR so we can see the results?

[igrigorik]

How are you integrating it with Travis. One way would be to make h2spec part of the default rake suite.. log all the output to stdout, exit with failure code if h2spec fails to mark build as failing.

[georgeu2000]

Yes, that is how it works, except h2spec failure does not mark build as failing.

https://github.com/georgeu2000/http-2/blob/000b8d8ef21493265fa7b8e8264959bcc1d644aa/.travis.yml

EDIT: It works as part of the travis build process. I can see some benefit to integrating with the default rake suite...

[igrigorik]

At a minimum, we should create a separate rake task to run the h2spec suite to make it more convenient to run locally. Also, default to "on" in CI is OK with me.

The only question to address before we land the CI integration though is to figure out if we want to enable that now, before we fix the h2spec issues, or after.

[georgeu2000]

I see your point. What's the purpose of CI if we ignore the result?

Let's skip h2spec CI for now. If we get many commits that break it we can reevaluate.

I'll create the rake task.

[ioquatix]

This is a great idea to follow up on. I'm going to add h2spec to async-http/falcon. It would be great to see it added here, especially to CI.

[HoneyryderChuck]

Closing this (h2spec added to CI)