h2spec http2/6.5.3/1 -p 9000 -o 5 : it hangs

[HoneyryderChuck]

./h2spec --version Version: 2.3.0 (cb03b47353d2691ede927b1d4a4ad9c417aeee60)

I have a very simple code: a socket accepting and printing the metadata. In ruby:

require "socket"

puts "Starting server on port 9000"
server = TCPServer.new(9000)

loop do
  sock = server.accept

  while !sock.closed? && !(sock.eof? rescue true) # rubocop:disable Style/RescueModifier
    puts sock.readpartial(1024).inspect
  end
end

When running the aforementioned spec, it hangs for 5 seconds, after which it opens a connection and immediately closes.

This doesn't seem correct, can anyone confirm it's a bug?

[HoneyryderChuck]

@summerwind I've narrowed this down to this snippet; the connection is somehow not properly established. If I comment this block, my test passes.

I've compared both created "conn"s, and the only different seems to be that the conn that passes the test has the max concurrent streams option set, and the other one hasn't:

# this one blocks on .Handshake()
conn: &{Conn:0xc0000b0270
Settings:map[]
Timeout:5s
Verbose:false
Closed:false
WindowUpdate:true
WindowSize:map[0:65535]
framer:0xc0001200c0
encoder:0xc0000b2600
encoderBuf:0xc00009b4d0
decoder:0xc000136480
debugFramer:<nil> debugFramerBuf:<nil>
server:false}

# this one is successfully initiated
conn: &{Conn:0xc00012a000
Settings:map[MAX_CONCURRENT_STREAMS:100]
Timeout:5s
Verbose:false
Closed:false
WindowUpdate:true
WindowSize:map[0:65535]
framer:0xc00012c000
encoder:0xc000126060
encoderBuf:0xc000128090
decoder:0xc000130000
debugFramer:<nil> debugFramerBuf:<nil>
server:false}

Do you have any idea on why this happens, or whether that check is really necessary?

[summerwind]

Can you show me the output of h2spec http2/6.5.3/1 -p 9000 -o 5 -v ?

[HoneyryderChuck]

sorry for the delay: here it is:

./h2spec http2/6.5.3/1 -p 9000 -o 5 -v
Hypertext Transfer Protocol Version 2 (HTTP/2)
  6. Frame Definitions
    6.5. SETTINGS
      6.5.3. Settings Synchronization
             [send] SETTINGS Frame (length:6, flags:0x00, stream_id:0)
        × 1: Sends multiple values of SETTINGS_INITIAL_WINDOW_SIZE
        Error: Timeout

[summerwind]

Thank you for the log.

This is not a bug. h2spec will wait a SETTINGS frame from your server to complete HTTP/2 handshake. So your server must send a SETTINGS frame.

See also: https://tools.ietf.org/html/rfc7540#section-3.5

[HoneyryderChuck]

Are you sure? The verbose log says that h2spec sent a settings frame, but my server never receives it, in fact, not even the magic handshake string arrives. Socket gets accepted and times out on read.

[summerwind]

Yes, I can see that your server's code receives handshake string and SETTINGS frame as follows.

$ ruby server.rb
Starting server on port 9000
"PRI * HTTP/2.0\r\n\r\nSM\r\n\r\n\x00\x00\x06\x04\x00\x00\x00\x00\x00\x00\x04\x00\x00\xFF\xFF"

Hmm, I don't know why the same message doesn't appear in your environment.

[HoneyryderChuck]

I'm using a macOS, what about you?

I've pulled wireshark, and I do see the packets going to the server, but the last one (that contains the settings) is marked as "101", not sure what that means... but I'm not getting the same as you.

[summerwind]

I'm using macOS Catalina and tested with h2spec v2.3.0.

[HoneyryderChuck]

I've opened a separate branch to run h2spec unpatched, and I'm getting the same errors in the CI: https://gitlab.com/honeyryderchuck/http-2-next/-/jobs/365589322 .