Add HTTP::Client logging and basic instrumentation

spec/std/http/client/client_spec.cr

@@ -3,6 +3,7 @@ require "../../socket/spec_helper"
 require "openssl"
 require "http/client"
 require "http/server"
+require "log/spec"
 
 private def test_server(host, port, read_time = 0, content_type = "text/plain", write_response = true)
   server = TCPServer.new(host, port)
@@ -300,5 +301,38 @@ module HTTP
         client.get("/")
       end
     end
+
+    describe "logging" do
+      it "emit logs" do
+        test_server("localhost", 0, content_type: "") do |server|
+          client = Client.new("localhost", server.local_address.port)
+          Log.capture("http.client") do |logs|
+            client.get("/")
+
+            logs.check(:debug, "Performing request")
+            logs.entry.data[:method].should eq("GET")
+            logs.entry.data[:host].should eq("localhost")
+            logs.entry.data[:port].should eq(server.local_address.port)
+            logs.entry.data[:resource].should eq("/")
+          end
+        end
+      end
+
+      it "emit logs with block" do
+        test_server("localhost", 0, content_type: "") do |server|
+          Client.new("localhost", server.local_address.port) do |client|
+            Log.capture("http.client") do |logs|
+              client.get("/") do |response|
+                logs.check(:debug, "Performing request")
+                logs.entry.data[:method].should eq("GET")
+                logs.entry.data[:host].should eq("localhost")
+                logs.entry.data[:port].should eq(server.local_address.port)
+                logs.entry.data[:resource].should eq("/")
+              end
+            end
+          end
+        end
+      end
+    end
   end
 end

src/http.cr

@@ -2,6 +2,7 @@ require "uri"
 {% unless flag?(:win32) %}
   require "./http/client"
   require "./http/server"
+  require "./http/log"
 {% end %}
 require "./http/common"
 

src/http/client.cr

@@ -577,7 +577,9 @@ class HTTP::Client
   # response.body # => "..."
   # ```
   def exec(request : HTTP::Request) : HTTP::Client::Response
-    exec_internal(request)
+    around_exec(request) do
+      exec_internal(request)
+    end
   end
 
   private def exec_internal(request)
@@ -615,8 +617,10 @@ class HTTP::Client
   # end
   # ```
   def exec(request : HTTP::Request, &block)
-    exec_internal(request) do |response|
-      yield response
+    around_exec(request) do
+      exec_internal(request) do |response|
+        yield response
+      end
     end
   end
 
@@ -862,6 +866,40 @@ class HTTP::Client
       yield client, path
     end
   end
+
+  # This method is called when executing the request. Although it can be
+  # redefined, it is recommended to use the `def_around_exec` macro to be
+  # able to add new behaviors without loosing prior existing ones.
+  protected def around_exec(request)
+    yield
+  end
+
+  # This macro allows injecting code to be run before and after the execution
+  # of the request. It should return the yielded value. It must be called with 1
+  # block argument that will be used to pass the `HTTP::Request`.
+  #
+  # ```
+  # class HTTP::Client
+  #   def_around_exec do |request|
+  #     # do something before exec
+  #     res = yield
+  #     # do something after exec
+  #     res
+  #   end
+  # end
+  # ```
+  macro def_around_exec(&block)
+    protected def around_exec(%request)
+      previous_def do
+        {% if block.args.size != 1 %}
+          {% raise "Wrong number of block arguments (given #{block.args.size}, expected: 1)" %}
+        {% end %}
+
+        {{ block.args.first.id }} = %request
+        {{ block.body }}
+      end
+    end
+  end
 end
 
 require "socket"

src/http/log.cr

@@ -0,0 +1,19 @@
+require "log"
+
+class HTTP::Client
+  Log = ::Log.for(self)
+
+  def_around_exec do |request|
+    emit_log(request)
+    yield
+  end
+
+  protected def emit_log(request)
+    Log.debug &.emit("Performing request",
+      method: request.method,
+      host: host,
+      port: port,
+      resource: request.resource,
+    )
+  end
+end