Multiple async-http client errors

[tleish]

We were having success with falcon in development, then we deployed to aws in a docker environment and ran into the following async-http client error.

error: #<Falcon::Adapters::Rack:0x00005642d4488100> [pid=8] [2020-05-23 14:12:09 +0000]
     |   Async::HTTP::Protocol::RequestFailed: Async::HTTP::Protocol::RequestFailed
     |   → /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/protocol/http2/response.rb:207 in `rescue in send_request'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/protocol/http2/response.rb:204 in `send_request'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/protocol/http2/client.rb:52 in `call'
     |     /usr/local/bundle/gems/protocol-http-0.12.3/lib/protocol/http/request.rb:51 in `call'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/client.rb:99 in `call'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/internet.rb:44 in `call'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/internet.rb:58 in `block (2 levels) in <class
     |     /home/app/lib/acme/falcon/http_client.rb:23 in `block (2 levels) in <class
     |     /usr/local/lib/ruby/2.6.0/forwardable.rb:230 in `post'
     |     /home/app/gems/acme/lib/acme/client.rb:22 in `block (2 levels) in <class
     |   Caused by NoMethodError: undefined method `bytesize' for :accept:Symbol
     |   → /usr/local/bundle/gems/protocol-hpack-1.4.1/lib/protocol/hpack/context.rb:325 in `size_check'
     |     /usr/local/bundle/gems/protocol-hpack-1.4.1/lib/protocol/hpack/context.rb:310 in `add_to_table'
     |     /usr/local/bundle/gems/protocol-hpack-1.4.1/lib/protocol/hpack/context.rb:205 in `decode'
     |     /usr/local/bundle/gems/protocol-hpack-1.4.1/lib/protocol/hpack/context.rb:232 in `block in encode'
     |     /usr/local/bundle/gems/protocol-http-0.12.3/lib/protocol/http/headers.rb:251 in `block (2 levels) in each'
     |     /usr/local/bundle/gems/protocol-http-0.12.3/lib/protocol/http/headers.rb:250 in `each'
     |     /usr/local/bundle/gems/protocol-http-0.12.3/lib/protocol/http/headers.rb:250 in `block in each'
     |     /usr/local/bundle/gems/protocol-http-0.12.3/lib/protocol/http/headers.rb:249 in `each'
     |     /usr/local/bundle/gems/protocol-http-0.12.3/lib/protocol/http/headers.rb:249 in `each'
     |     /usr/local/bundle/gems/protocol-hpack-1.4.1/lib/protocol/hpack/context.rb:227 in `encode'
     |     /usr/local/bundle/gems/protocol-hpack-1.4.1/lib/protocol/hpack/compressor.rb:193 in `encode'
     |     /usr/local/bundle/gems/protocol-http2-0.9.7/lib/protocol/http2/connection.rb:113 in `encode_headers'
     |     /usr/local/bundle/gems/protocol-http2-0.9.7/lib/protocol/http2/stream.rb:235 in `block in write_headers'
     |     /usr/local/bundle/gems/protocol-http2-0.9.7/lib/protocol/http2/connection.rb:232 in `write_frames'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/protocol/http2/connection.rb:81 in `block in write_frames'
     |     /usr/local/bundle/gems/async-1.23.0/lib/async/semaphore.rb:76 in `acquire'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/protocol/http2/connection.rb:80 in `write_frames'
     |     /usr/local/bundle/gems/protocol-http2-0.9.7/lib/protocol/http2/stream.rb:234 in `write_headers'
     |     /usr/local/bundle/gems/protocol-http2-0.9.7/lib/protocol/http2/stream.rb:248 in `send_headers'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/protocol/http2/response.rb:205 in `send_request'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/protocol/http2/client.rb:52 in `call'
     |     /usr/local/bundle/gems/protocol-http-0.12.3/lib/protocol/http/request.rb:51 in `call'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/client.rb:99 in `call'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/internet.rb:44 in `call'
     |     /usr/local/bundle/gems/async-http-0.48.2/lib/async/http/internet.rb:58 in `block (2 levels) in <class
     |     /home/app/lib/acme/falcon/http_client.rb:23 in `block (2 levels) in <class
     |     /usr/local/lib/ruby/2.6.0/forwardable.rb:230 in `post'
     |     /home/app/gems/acme/lib/acme/client.rb:22 in `block (2 levels) in <class

Thinking it might be because we are a bit out of date, we upgraded falcon and async-http to the latest and now have new errors:

error: Falcon::Adapters::Rack [oid=0x2aff139f9c90] [pid=8] [2020-05-23 15:00:23 +0000]
     |   NoMethodError: undefined method `split' for 1590246023.4250834:Float
     |   → /usr/local/bundle/gems/protocol-http-0.20.0/lib/protocol/http/header/split.rb:31 in `initialize'
     |     /usr/local/bundle/gems/protocol-http-0.20.0/lib/protocol/http/headers.rb:284 in `new'
     |     /usr/local/bundle/gems/protocol-http-0.20.0/lib/protocol/http/headers.rb:284 in `merge_into'
     |     /usr/local/bundle/gems/protocol-http-0.20.0/lib/protocol/http/headers.rb:299 in `block in to_h'
     |     /usr/local/bundle/gems/protocol-http-0.20.0/lib/protocol/http/headers.rb:298 in `each'
     |     /usr/local/bundle/gems/protocol-http-0.20.0/lib/protocol/http/headers.rb:298 in `inject'
     |     /usr/local/bundle/gems/protocol-http-0.20.0/lib/protocol/http/headers.rb:298 in `to_h'
     |     /usr/local/bundle/gems/protocol-http-0.20.0/lib/protocol/http/headers.rb:293 in `[]'
     |     /usr/local/bundle/gems/protocol-http-0.20.0/lib/protocol/http/headers.rb:152 in `include?'
     |     /usr/local/bundle/gems/protocol-http-0.20.0/lib/protocol/http/headers.rb:111 in `trailers!'
     |     /usr/local/bundle/gems/async-http-0.52.4/lib/async/http/protocol/http1/client.rb:34 in `call'
     |     /usr/local/bundle/gems/protocol-http-0.20.0/lib/protocol/http/request.rb:53 in `call'
     |     /usr/local/bundle/gems/async-http-0.52.4/lib/async/http/client.rb:143 in `make_response'
     |     /usr/local/bundle/gems/async-http-0.52.4/lib/async/http/client.rb:106 in `call'
     |     /usr/local/bundle/gems/async-http-0.52.4/lib/async/http/internet.rb:53 in `call'
     |     /usr/local/bundle/gems/async-http-0.52.4/lib/async/http/internet.rb:70 in `block (2 levels) in <class
     |     /home/app/lib/acme/falcon/http_client.rb:23 in `block (2 levels) in <class
     |     /usr/local/lib/ruby/2.6.0/forwardable.rb:230 in `post'
     |     /home/app/gems/acme/lib/acme/client.rb:24 in `block (2 levels) in <class

I'm not sure if the upgrade resolved the old issue and added a new one, or if it hit this error before hitting the next error.

[ioquatix]

It seems like in development you were using HTTP/1 and in production maybe HTTP/2.

Your header key/values are not strings. However, this should be normalised internally, so I'll investigate what is going on.

[ioquatix]

I have not had a chance to look into this much yet, but I can confirm one fix would be to ensure your hash keys and values are strings. However, this might be an oversight on my part, so I'd suggest holding off until I can take a closer look, which I'll endeavour to do so this week.

[tleish]

Ah, based on your tip the second error must be coming from this header key/value:

{
   ...
   'X-Started-At': Time.now.to_f
}

which explains

NoMethodError: undefined method `split' for 1590246023.4250834:Float

[tleish]

I also have a different header for another call which includes:

{
   ...
   'Accept': 'application/json',
}

Would this have caused the previous error of:

Caused by NoMethodError: undefined method `bytesize' for :accept:Symbol

The error shows accept symbol in lower case, while the code declared it in upper.

[ioquatix]

I’m in bed but yes that key is probably a symbol, please use a string and report back. I’m planning to add specs for these cases tomorrow so I can review the details and lock down the semantics.

[tleish]

FYI, updated header key/values to all be strings and I no longer receive the prior reported errors. You can close this issue, unless you want to leave it open in order to update the client library to handle non-string key/values.

[ioquatix]

Yeah, at the very least it should probably issue a warning. I'm going to leave it open for now.

[tleish]

FYI, as an easy fix I added the following in a wrapper clas:

headers.transform_keys(&:to_s).transform_values(&:to_s)

[ioquatix]

Okay.

So, enforcing this is not free.

It's also not obvious what should be enforced.

HTTP/1 is relatively flexible.

HTTP/2 is less flexible.

The best option might be to put this into Protocol::HTTP::Headers::Merged which should mitigate the issue:

                # @yield [String, String] header key (lower case) and value (as string).
                def each(&block)
                    @all.each do |headers|
                        headers.each do |key, value|
                            yield key.to_s.downcase, value.to_s
                        end
                    end
                end

This turns everything into a normal form.

However, this imposes a cost to all users, even if they do the right thing.

The spec looks something like this:

    context 'with headers' do
        let(:server) do
            Async::HTTP::Server.for(endpoint, protocol) do |request|
                Protocol::HTTP::Response[200, [], request.headers.inspect]
            end
        end

        it 'fails when headers are not strings' do
            response = client.get("/", {foo: 'bar'})
            expect(response).to be_success
        end
    end

Should we expect this to pass?

[ioquatix]

The other option is to enable verbose logging of headers but only when debug logging is turned on. This could pick up issues before they happen.

[ioquatix]

There is a performance cost to this fix, but it might be unavoidable and in practice is probably undetectable. That being said, we could consider adding a warning to this code path because honestly, header keys should always be lower case strings, and header values should always be strings.

[ioquatix]

Released in protocol-http v0.23.2.