From 534cc0c8c1d246f368f9fdfb88dad3ff9025f43d Mon Sep 17 00:00:00 2001 From: "Brian J. Cardiff" Date: Thu, 17 Sep 2020 12:33:38 -0300 Subject: [PATCH 1/4] Add HTTP::Client logging and basic instrumentation This adds protected methods HTTP::Client#before_exec and #after_exec that can be used to hook into the lifecycle of the http client. A first utility for this is adding a http.client log source to know a request is starting. This enables some basic instrumentation to monitor the activity of the application without monkey patching sensitive parts of the http client --- spec/std/http/client/client_spec.cr | 34 +++++++++++++++++++++++++++++ src/http.cr | 1 + src/http/client.cr | 12 ++++++++++ src/http/log.cr | 19 ++++++++++++++++ 4 files changed, 66 insertions(+) create mode 100644 src/http/log.cr diff --git a/spec/std/http/client/client_spec.cr b/spec/std/http/client/client_spec.cr index e7dc6443b0b7..e9802761d9de 100644 --- a/spec/std/http/client/client_spec.cr +++ b/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 diff --git a/src/http.cr b/src/http.cr index facbdd2f897c..33cbc7895b39 100644 --- a/src/http.cr +++ b/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" diff --git a/src/http/client.cr b/src/http/client.cr index bc032ac0b986..1920a9f4652c 100644 --- a/src/http/client.cr +++ b/src/http/client.cr @@ -577,7 +577,10 @@ class HTTP::Client # response.body # => "..." # ``` def exec(request : HTTP::Request) : HTTP::Client::Response + before_exec(request) exec_internal(request) + ensure + after_exec(request) end private def exec_internal(request) @@ -615,9 +618,12 @@ class HTTP::Client # end # ``` def exec(request : HTTP::Request, &block) + before_exec(request) exec_internal(request) do |response| yield response end + ensure + after_exec(request) end private def exec_internal(request, &block : Response -> T) : T forall T @@ -862,6 +868,12 @@ class HTTP::Client yield client, path end end + + protected def before_exec(request) + end + + protected def after_exec(request) + end end require "socket" diff --git a/src/http/log.cr b/src/http/log.cr new file mode 100644 index 000000000000..2d9d01fd2cd5 --- /dev/null +++ b/src/http/log.cr @@ -0,0 +1,19 @@ +require "log" + +class HTTP::Client + Log = ::Log.for(self) + + protected def before_exec(request) + previous_def + emit_log(request) + end + + protected def emit_log(request) + Log.debug &.emit("Performing request", + method: request.method, + host: host, + port: port, + resource: request.resource, + ) + end +end From f98d898a784226259b09068a3ddfc907957eed37 Mon Sep 17 00:00:00 2001 From: "Brian J. Cardiff" Date: Thu, 17 Sep 2020 15:59:15 -0300 Subject: [PATCH 2/4] Replace with use def_around_exec macro --- src/http/client.cr | 26 +++++++++++++++----------- src/http/log.cr | 6 +++--- 2 files changed, 18 insertions(+), 14 deletions(-) diff --git a/src/http/client.cr b/src/http/client.cr index 1920a9f4652c..10fb422ada51 100644 --- a/src/http/client.cr +++ b/src/http/client.cr @@ -577,10 +577,9 @@ class HTTP::Client # response.body # => "..." # ``` def exec(request : HTTP::Request) : HTTP::Client::Response - before_exec(request) - exec_internal(request) - ensure - after_exec(request) + around_exec(request) do + exec_internal(request) + end end private def exec_internal(request) @@ -618,12 +617,11 @@ class HTTP::Client # end # ``` def exec(request : HTTP::Request, &block) - before_exec(request) - exec_internal(request) do |response| - yield response + around_exec(request) do + exec_internal(request) do |response| + yield response + end end - ensure - after_exec(request) end private def exec_internal(request, &block : Response -> T) : T forall T @@ -869,10 +867,16 @@ class HTTP::Client end end - protected def before_exec(request) + protected def around_exec(request) + yield request end - protected def after_exec(request) + macro def_around_exec + protected def around_exec(request) + previous_def do + {{ yield :request.id }} + end + end end end diff --git a/src/http/log.cr b/src/http/log.cr index 2d9d01fd2cd5..e598c42008ed 100644 --- a/src/http/log.cr +++ b/src/http/log.cr @@ -3,9 +3,9 @@ require "log" class HTTP::Client Log = ::Log.for(self) - protected def before_exec(request) - previous_def - emit_log(request) + def_around_exec do |request| + emit_log({{request}}) + yield end protected def emit_log(request) From 46d4fd823239045d819b1c883037c106aa3c8169 Mon Sep 17 00:00:00 2001 From: "Brian J. Cardiff" Date: Thu, 17 Sep 2020 16:45:54 -0300 Subject: [PATCH 3/4] Manually expand macro to allow simple usage of def_around_exec --- src/http/client.cr | 13 +++++++++---- src/http/log.cr | 2 +- 2 files changed, 10 insertions(+), 5 deletions(-) diff --git a/src/http/client.cr b/src/http/client.cr index 10fb422ada51..a41b103f228c 100644 --- a/src/http/client.cr +++ b/src/http/client.cr @@ -868,13 +868,18 @@ class HTTP::Client end protected def around_exec(request) - yield request + yield end - macro def_around_exec - protected def around_exec(request) + macro def_around_exec(&block) + protected def around_exec(%request) previous_def do - {{ yield :request.id }} + {% 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 diff --git a/src/http/log.cr b/src/http/log.cr index e598c42008ed..7f16c4c63e90 100644 --- a/src/http/log.cr +++ b/src/http/log.cr @@ -4,7 +4,7 @@ class HTTP::Client Log = ::Log.for(self) def_around_exec do |request| - emit_log({{request}}) + emit_log(request) yield end From 892428e21c5fd711afa49f782780a911bb2c57b1 Mon Sep 17 00:00:00 2001 From: "Brian J. Cardiff" Date: Thu, 17 Sep 2020 17:51:42 -0300 Subject: [PATCH 4/4] Add docs --- src/http/client.cr | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/src/http/client.cr b/src/http/client.cr index a41b103f228c..822a63e43de4 100644 --- a/src/http/client.cr +++ b/src/http/client.cr @@ -867,10 +867,27 @@ class HTTP::Client 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