Add logging and instrumentation via features

lib/http.rb

@@ -10,6 +10,7 @@
 require "http/client"
 require "http/connection"
 require "http/options"
+require "http/feature"
 require "http/request"
 require "http/request/writer"
 require "http/response"

lib/http/client.rb

@@ -4,6 +4,7 @@
 
 require "http/form_data"
 require "http/options"
+require "http/feature"
 require "http/headers"
 require "http/connection"
 require "http/redirector"

lib/http/feature.rb

@@ -15,3 +15,8 @@ def wrap_response(response)
     end
   end
 end
+
+require "http/features/auto_inflate"
+require "http/features/auto_deflate"
+require "http/features/logging"
+require "http/features/instrumentation"

lib/http/features/auto_deflate.rb

@@ -40,6 +40,8 @@ def deflated_body(body)
         end
       end
 
+      HTTP::Options.register_feature(:auto_deflate, self)
+
       class CompressedBody < HTTP::Request::Body
         def initialize(uncompressed_body)
           @body       = uncompressed_body

lib/http/features/auto_inflate.rb

@@ -18,6 +18,8 @@ def wrap_response(response)
       def stream_for(connection)
         Response::Body.new(Response::Inflater.new(connection))
       end
+
+      HTTP::Options.register_feature(:auto_inflate, self)
     end
   end
 end

lib/http/features/instrumentation.rb

@@ -0,0 +1,56 @@
+# frozen_string_literal: true
+
+module HTTP
+  module Features
+    # Instrument requests and responses. Expects an
+    # ActiveSupport::Notifications-compatible instrumenter. Defaults to use a
+    # namespace of 'http' which may be overridden with a `:namespace` param.
+    # Emits a single event like `"request.{namespace}"`, eg `"request.http"`.
+    # Be sure to specify the instrumenter when enabling the feature:
+    #
+    #    HTTP
+    #      .use(instrumentation: {instrumenter: ActiveSupport::Notifications})
+    #      .get("https://example.com/")
+    #
+    class Instrumentation
+      attr_reader :instrumenter, :name
+
+      def initialize(instrumenter: NullInstrumenter.new, namespace: "http")
+        @instrumenter = instrumenter
+        @name = "request.#{namespace}"
+      end
+
+      def wrap_request(request)
+        instrumenter.instrument("start_#{name}", :request => request)
+        instrumenter.start(name, :request => request)
+        request
+      end
+
+      def wrap_response(response)
+        instrumenter.finish(name, :response => response)
+        response
+      end
+
+      HTTP::Options.register_feature(:instrumentation, self)
+
+      class NullInstrumenter
+        def instrument(name, payload = {})
+          start(name, payload)
+          begin
+            yield payload if block_given?
+          ensure
+            finish name, payload
+          end
+        end
+
+        def start(_name, _payload)
+          true
+        end
+
+        def finish(_name, _payload)
+          true
+        end
+      end
+    end
+  end
+end

lib/http/features/logging.rb

@@ -0,0 +1,55 @@
+# frozen_string_literal: true
+
+module HTTP
+  module Features
+    # Log requests and responses. Request verb and uri, and Response status are
+    # logged at `info`, and the headers and bodies of both are logged at
+    # `debug`. Be sure to specify the logger when enabling the feature:
+    #
+    #    HTTP.use(logging: {logger: Logger.new(STDOUT)}).get("https://example.com/")
+    #
+    class Logging < Feature
+      attr_reader :logger
+
+      def initialize(logger: NullLogger.new)
+        @logger = logger
+      end
+
+      def wrap_request(request)
+        logger.info { "> #{request.verb.to_s.upcase} #{request.uri}" }
+        logger.debug do
+          headers = request.headers.map { |name, value| "#{name}: #{value}" }.join("\n")
+          body = request.body.source
+
+          headers + "\n\n" + body.to_s
+        end
+        request
+      end
+
+      def wrap_response(response)
+        logger.info { "< #{response.status}" }
+        logger.debug do
+          headers = response.headers.map { |name, value| "#{name}: #{value}" }.join("\n")
+          body = response.body.to_s
+
+          headers + "\n\n" + body
+        end
+        response
+      end
+
+      class NullLogger
+        %w[fatal error warn info debug].each do |level|
+          define_method(level.to_sym) do |*_args|
+            nil
+          end
+
+          define_method(:"#{level}?") do
+            true
+          end
+        end
+      end
+
+      HTTP::Options.register_feature(:logging, self)
+    end
+  end
+end

lib/http/options.rb

@@ -1,24 +1,18 @@
 # frozen_string_literal: true
 
-# rubocop:disable Metrics/ClassLength, Style/RedundantSelf
+# rubocop:disable Metrics/ClassLength
 
 require "http/headers"
 require "openssl"
 require "socket"
 require "http/uri"
-require "http/feature"
-require "http/features/auto_inflate"
-require "http/features/auto_deflate"
 
 module HTTP
   class Options
     @default_socket_class     = TCPSocket
     @default_ssl_socket_class = OpenSSL::SSL::SSLSocket
     @default_timeout_class    = HTTP::Timeout::Null
-    @available_features       = {
-      :auto_inflate => Features::AutoInflate,
-      :auto_deflate => Features::AutoDeflate
-    }
+    @available_features       = {}
 
     class << self
       attr_accessor :default_socket_class, :default_ssl_socket_class, :default_timeout_class
@@ -33,6 +27,10 @@ def defined_options
         @defined_options ||= []
       end
 
+      def register_feature(name, impl)
+        @available_features[name] = impl
+      end
+
       protected
 
       def def_option(name, reader_only: false, &interpreter)
@@ -74,12 +72,12 @@ def initialize(options = {}) # rubocop:disable Style/OptionHash
       opts_w_defaults.each { |(k, v)| self[k] = v }
     end
 
-    def_option :headers do |headers|
-      self.headers.merge(headers)
+    def_option :headers do |new_headers|
+      headers.merge(new_headers)
     end
 
-    def_option :cookies do |cookies|
-      cookies.each_with_object self.cookies.dup do |(k, v), jar|
+    def_option :cookies do |new_cookies|
+      new_cookies.each_with_object cookies.dup do |(k, v), jar|
         cookie = k.is_a?(Cookie) ? k : Cookie.new(k.to_s, v.to_s)
         jar[cookie.name] = cookie.cookie_value
       end
@@ -89,23 +87,23 @@ def initialize(options = {}) # rubocop:disable Style/OptionHash
       self.encoding = Encoding.find(encoding)
     end
 
-    def_option :features, :reader_only => true do |features|
+    def_option :features, :reader_only => true do |new_features|
       # Normalize features from:
       #
       #     [{feature_one: {opt: 'val'}}, :feature_two]
       #
       # into:
       #
       #     {feature_one: {opt: 'val'}, feature_two: {}}
-      features = features.each_with_object({}) do |feature, h|
+      normalized_features = new_features.each_with_object({}) do |feature, h|
         if feature.is_a?(Hash)
           h.merge!(feature)
         else
           h[feature] = {}
         end
       end
 
-      self.features.merge(features)
+      features.merge(normalized_features)
     end
 
     def features=(features)

spec/lib/http/features/instrumentation_spec.rb

@@ -0,0 +1,56 @@
+# frozen_string_literal: true
+
+RSpec.describe HTTP::Features::Instrumentation do
+  subject(:feature) { HTTP::Features::Instrumentation.new(:instrumenter => instrumenter) }
+  let(:instrumenter) { TestInstrumenter.new }
+
+  describe "logging the request" do
+    let(:request) do
+      HTTP::Request.new(
+        :verb => :post,
+        :uri => "https://example.com/",
+        :headers => {:accept => "application/json"},
+        :body => '{"hello": "world!"}'
+      )
+    end
+
+    it "should log the request" do
+      feature.wrap_request(request)
+
+      expect(instrumenter.output[:start]).to eq(:request => request)
+    end
+  end
+
+  describe "logging the response" do
+    let(:response) do
+      HTTP::Response.new(
+        :version => "1.1",
+        :uri => "https://example.com",
+        :status => 200,
+        :headers => {:content_type => "application/json"},
+        :body => '{"success": true}'
+      )
+    end
+
+    it "should log the response" do
+      feature.wrap_response(response)
+
+      expect(instrumenter.output[:finish]).to eq(:response => response)
+    end
+  end
+
+  class TestInstrumenter < HTTP::Features::Instrumentation::NullInstrumenter
+    attr_reader :output
+    def initialize
+      @output = {}
+    end
+
+    def start(_name, payload)
+      output[:start] = payload
+    end
+
+    def finish(_name, payload)
+      output[:finish] = payload
+    end
+  end
+end

spec/lib/http/features/logging_spec.rb

@@ -0,0 +1,74 @@
+# frozen_string_literal: true
+
+RSpec.describe HTTP::Features::Logging do
+  subject(:feature) { HTTP::Features::Logging.new(:logger => logger) }
+  let(:logger) { TestLogger.new }
+
+  describe "logging the request" do
+    let(:request) do
+      HTTP::Request.new(
+        :verb => :post,
+        :uri => "https://example.com/",
+        :headers => {:accept => "application/json"},
+        :body => '{"hello": "world!"}'
+      )
+    end
+
+    it "should log the request" do
+      feature.wrap_request(request)
+
+      expect(logger.output).to eq(
+        [
+          "> POST https://example.com/",
+          <<~REQ.strip
+            Accept: application/json
+            Host: example.com
+            User-Agent: http.rb/4.0.0.dev
+
+            {"hello": "world!"}
+          REQ
+        ]
+      )
+    end
+  end
+
+  describe "logging the response" do
+    let(:response) do
+      HTTP::Response.new(
+        :version => "1.1",
+        :uri => "https://example.com",
+        :status => 200,
+        :headers => {:content_type => "application/json"},
+        :body => '{"success": true}'
+      )
+    end
+
+    it "should log the response" do
+      feature.wrap_response(response)
+
+      expect(logger.output).to eq(
+        [
+          "< 200 OK",
+          <<~REQ.strip
+            Content-Type: application/json
+
+            {"success": true}
+          REQ
+        ]
+      )
+    end
+  end
+
+  class TestLogger
+    attr_reader :output
+    def initialize
+      @output = []
+    end
+
+    %w[fatal error warn info debug].each do |level|
+      define_method(level.to_sym) do |*args, &block|
+        @output << (block ? block.call : args)
+      end
+    end
+  end
+end