Add HTTP::Client logging and basic instrumentation

[bcardiff]

(Update: see #9756 (comment) for the final state of the PR)

---

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.

---

As an example if one wants to log also when a request is completed and measure the elapsed time the app could define

class HTTP::Client
  protected def before_exec(request)
    previous_def
    @start = Time.monotonic
  end

  protected def after_exec(request)
    previous_def
    elapsed = Time.monotonic - @start.not_nil!
    Log.debug &.emit("Finished request",
      method: request.method,
      host: host,
      port: port,
      resource: request.resource,
      elapsed: "#{elapsed.total_seconds.humanize(precision: 2, significant: false)}s"
    )
  end
end

[asterite]

I think it's simpler to do something like around_request. That way for measuring time you don't need to add an instance variable.

[asterite]

Also, using previous_def seems like a smell to me, but maybe it's the most efficient way to do something like AOP or event callbacks without having to add to a list, keep that list in memory, iterate it and call each processor, etc. So maybe it's fine.

[bcardiff]

around_exec can also work, I found before/after simpler.

Would it be better to have only around? or around + before + after?

[asterite]

Something like this: (I'm surprised it works with just yield, which is nice)

class Foo
  def foo
    around_foo do
      1
    end
  end

  protected def around_foo
    yield
  end

  macro def_around_foo
    protected def around_foo
      previous_def do
        {{yield}}
      end
    end
  end
end

class Foo
  def_around_foo do
    time = Time.local
    value = yield
    puts Time.local - time
    value
  end
end

Foo.new.foo

Also with a macro it's simpler, the internal protected name doesn't matter anymore, and the way hooks are defined could be changed later on if needed. And the macro can be documented.

[asterite]

I think it's simpler to have just around. In fact, this is already pretty much #6011 which begs for handlers, similar to how you can add handlers (middlewares) to an http server.

In this way, you could create an http client, enable logging, or introduce a proxy, whatever, without affecting other clients. So instead of just adding logging I would try to focus on the general solution (if there's time, and someone wants to do it).

[bcardiff]

The around macro has as a drawback that the block argument is an ast node and hence it must be {{-ed.

The example to measure the elapsed time can be done in either way after the last commit

class HTTP::Client
  def_around_exec do |request|
    start = Time.monotonic
    begin
      yield
    ensure
      elapsed = Time.monotonic - start.not_nil!

      Log.debug &.emit("Finished request",
        method: {{request}}.method,
        host: host,
        port: port,
        resource: {{request}}.resource,
        elapsed: "#{elapsed.total_seconds.humanize(precision: 2, significant: false)}s"
      )
    end
  end
end

or

class HTTP::Client
  def_around_exec do |request|
    start = Time.monotonic
    res = yield
    elapsed = Time.monotonic - start

    Log.debug &.emit("Finished request",
      method: {{request}}.method,
      host: host,
      port: port,
      resource: {{request}}.resource,
      elapsed: "#{elapsed.total_seconds.humanize(precision: 2, significant: false)}s"
    )
    res
  end
end

The other alternative is to move the around method to HTTP::Request instead of the client.

[asterite]

Yeah, I agree it's ugly. Another alternative is to continue using around but not using a macro for it.

Also, how do I try this out? I can't setup logging...

[bcardiff]

@asterite by default only info severity is advertised. You can do

Log.setup_from_env

HTTP::Client.get("https://google.com")
HTTP::Client.get("http://example.org") do |resp|
end

$ LOG_LEVEL=DEBUG bin/crystal foo.cr

[asterite]

It's possible to do it like this:

  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

Then you can use whatever name you want in the block.

[asterite]

I have this, I'm not seeing any logs in stdout:

require "http/client"

class HTTP::Client
  def_around_exec do |request|
    start = Time.monotonic
    value = yield request
    elapsed = Time.monotonic - start.not_nil!
    Log.error &.emit("Finished request",
      method: request.method,
      host: host,
      port: port,
      resource: request.resource,
      elapsed: "#{elapsed.total_seconds.humanize(precision: 2, significant: false)}s"
    )
    value
  end
end

Log.setup_from_env

HTTP::Client.get("https://www.example.com").to_io(STDOUT)

[bcardiff]

@asterite it's example.org not example.com. $ curl -v https://www.example.com never ends for me.

I sent that patch. It can work that way I think 👍

[asterite]

example.com works for me

I changed it to example.org but I can't see any logging in stdout

[bcardiff]

Rebased on master. Ready for review.

[bcardiff]

The final state of this PR is

This adds the macro HTTP::Client.def_around_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.

---

As an example if one wants to log also when a request is completed and measure the elapsed time the app could define

class HTTP::Client
  def_around_exec do |request|
    start = Time.monotonic

    res = yield

    elapsed = Time.monotonic - start
    Log.debug &.emit("Finished request",
      method: request.method,
      host: host,
      port: port,
      resource: request.resource,
      elapsed: "#{elapsed.total_seconds.humanize(precision: 2, significant: false)}s"
    )

    res
  end
end