Fix global logger setting interfering with response deflation parsing

[bkuhlmann]

Why

Hello. 👋

I discovered a rather hard to debug situation when using HTTP's global configuration to configure logging and then ending up with a JSON parsing error due to an empty string in the HTTP response due compression (i.e. making an HTTP request where the content is in gzip format).

How

Here's how to recreate the issue quickly using the following script:

#! /usr/bin/env ruby
# frozen_string_literal: true

# Save as `demo`, then `chmod 755 demo`, and run as `./demo`.

require "bundler/inline"

gemfile true do
  source "https://rubygems.org"

  gem "amazing_print"
  gem "debug"
  gem "http"
  gem "json"
  gem "logger"
end

uri = "https://alchemists.io/api/alfred/projects.json"
logger = Logger.new STDOUT

HTTP.default_options = HTTP::Options.new features: {logging: {logger:}}

HTTP.use(:auto_inflate)
    .get("https://alchemists.io/api/alfred/projects.json")
    .then { it.parse }
    .then { puts it }

The above will result in the following error:

json-2.15.2/lib/json/common.rb:358:in 'JSON::Ext::Parser.parse': unexpected end of input at line 1 column 1 (JSON::ParserError)

The problem is that the global logger configuration ends up parsing the body first (roughly speaking) before the HTTP response can be parsed. This causes the above error because by the time you ask the HTTP response to parse itself, you only have an empty string at that point.

The workaround to the above is to not define the logger as a global default but use the logger in each request. For example, the following will work:

HTTP.use(:auto_inflate)
    .use(logging: {logger: logger})
    .get(uri)
    .then { it.parse }
    .then { puts it }

Would it be possible to ensure setting a global logger doesn't interfere with the final parsing of the result?

Notes

By the way, if setting the logger per each request is the only way to handle this, is there harm in using a single HTTP instance throughout your entire application? Example:

CLIENT = HTTP.use(:auto_inflate).use(logging: {logger: logger})

This way you could semi-provide a global configuration for HTTP that works. The only problem is that I haven't tested this over extensive use to see if there memory leaks or concurrency issues using HTTP like this.

[paul]

Hi @bkuhlmann!

I almost always do what you suggested, in any project that isn't just a one-off script. Instead of using the HTTP global directly, create one for the app with various settings:

require "connection_pool"
require "http"

module MyApp
  HTTP = ConnectionPool::Wrapper.new(size: EnvConfig.threads) do
    ::HTTP.timeout(connect: 2.seconds, read: 10.seconds, write: 10.seconds)
      .use(logging: { logger: Rails.logger })
      .use(:tracing)
      .headers("User-Agent" => "http.rb/#{::HTTP::VERSION} - MyApp")
  end
end

[bkuhlmann]

Hey Paul, thanks! 🙇

This is quite nice as I ended up updating my HTTP Hanami provider as follows:

Hanami.app.register_provider :http do
  prepare do
    require "connection_pool"
    require "http"
  end

  start do
    slice.start :logger

    http = ConnectionPool::Wrapper.new size: ENV.fetch("HANAMI_MAX_THREADS", 5) do
      HTTP.timeout(connect: 2, read: 10, write: 10)
          .use(logging: {logger: slice[:logger]})
          .headers("User-Agent" => "http.rb/#{HTTP::VERSION} - Demo")
    end

    register :http, http
  end
end

I've made a note to wire up tracing at some point as well.