New step: Log request/response

[wojtekmach]

TBD the naming and output formatting but basically we want to dump the raw request and response for debugging. Something like this:

It's using logger so that users can enable this in tests but also set @tag :capture_log, i.e. see this only when the tests fail.

HTTPie has interesting options for output formatting:

  --print WHAT, -p WHAT
      String specifying what the output should contain:

          'H' request headers
          'B' request body
          'h' response headers
          'b' response body
          'm' response metadata

      The default behaviour is 'hb' (i.e., the response
      headers and body is printed), if standard output is not redirected.
      If the output is piped to another program or to a file, then only the
      response body is printed by default.

so we might look into something like that too. Or, we double-down on logger and expose variables to be used by formatting configuration:

"\n$time $metadata[$level] $message\n"

cc @reisub

[wojtekmach]

:log as an option name might be a bit too broad. Since this option will most likely be used in tests and so possibly configured via:

# test/test_helper.exs
Req.default_options(...)

then it's ok if it's a bit verbose. So another suggestion is to have:

Req.new(
  log_request: true | format,
  log_response: true | format
)

[thenrio]

Hi there, this would be useful indeed.
I made a req plugin for that, for our own use, with goal to see in our log what we send and receive, for rehearsal purpose when we integrate a new provider, on a given environment.

I used

• Logger at debug level, and switch it on/off on server using Logger.put_module_level/2.
• a private id for request, so that I can track the request and its response in the server log

An excerpt output is:

[debug] 0000005 > GET http://httpbin.org/status/401
[debug] 0000005 > accept-encoding: gzip
[debug] 0000005 > user-agent: req/0.4.3
[debug] 0000005 >
[debug] 0000005 < 401
[debug] 0000005 < access-control-allow-credentials: true
[debug] 0000005 < access-control-allow-origin: *
[debug] 0000005 < connection: keep-alive
[debug] 0000005 < content-length: 0
[debug] 0000005 < date: Fri, 06 Oct 2023 09:45:36 GMT
[debug] 0000005 < server: gunicorn/19.9.0
[debug] 0000005 < www-authenticate: Basic realm="Fake Realm"
[debug] 0000005 <

Implementation was straightforward (Request.append_request_steps/2, Request.prepend_response_steps) until until I met gzipped response, so I end up with steps like:
request_steps : [..., :log_request, :compress_body]
response_steps : [:log_response_head, ..., :decompress_body, :log_response_body, ...]

Cheers.

[adriankumpf]

Another use case outside of testing that I'm particularly interested in is logging the request method, URL, response status, and most importantly, the time taken.

Similar to tesla's Logger middleware:

GET https://example.com -> 200 (88.074 ms)

I tried to write a req plugin for my own use, but had trouble getting the time measurement to work when a request is retried.

[rhcarvalho]

but had trouble getting the time measurement to work when a request is retried.

I was considering this too for a plugin, and, since the request steps never run a second time (do not run for the retries), what can be done is inspect :req_retry_count in request.private and associate your timings with each run.

You could use a custom adapter that wraps Finch (or any other "real" adapter), times the request and store it/log it.

[venkatd]

Hi there, this would be useful indeed. I made a req plugin for that, for our own use, with goal to see in our log what we send and receive, for rehearsal purpose when we integrate a new provider, on a given environment.

I used

• Logger at debug level, and switch it on/off on server using Logger.put_module_level/2.
• a private id for request, so that I can track the request and its response in the server log

An excerpt output is:

[debug] 0000005 > GET http://httpbin.org/status/401
[debug] 0000005 > accept-encoding: gzip
[debug] 0000005 > user-agent: req/0.4.3
[debug] 0000005 >
[debug] 0000005 < 401
[debug] 0000005 < access-control-allow-credentials: true
[debug] 0000005 < access-control-allow-origin: *
[debug] 0000005 < connection: keep-alive
[debug] 0000005 < content-length: 0
[debug] 0000005 < date: Fri, 06 Oct 2023 09:45:36 GMT
[debug] 0000005 < server: gunicorn/19.9.0
[debug] 0000005 < www-authenticate: Basic realm="Fake Realm"
[debug] 0000005 <

Implementation was straightforward (Request.append_request_steps/2, Request.prepend_response_steps) until until I met gzipped response, so I end up with steps like: request_steps : [..., :log_request, :compress_body] response_steps : [:log_response_head, ..., :decompress_body, :log_response_body, ...]

Cheers.

Hi @thenrio I would love to get a hold of this code if you are able to share it :)

I am trying to debug some http requests by comparing the request/response and seeing the raw request would be extremely helpful.

[thenrio]

@venkatd Something like that?

defmodule Req.Plugins.Log do
  @moduledoc """
  Logs request and response.
  Log is made using Logger facility at debug level.

  If needbe, you can adjust the module log level:

      Logger.put_module_level(Req.Plugins.Log, :debug)


  And revert it back:

      Logger.delete_module_level(Req.Plugins.Log)

  Log message has structure, in EBNF like:

  log   := id space way space data
  id    := digit{7}
  space := " "
  way   := ">" | "<"
  data  := any

  way is > for outgoing request, < for incoming response.
  eg:

  0000001 > GET http://httpbin.org/status/401
  0000001 > accept-encoding: gzip
  0000001 > user-agent: req/0.4.3
  0000001 >
  0000001 < 401
  0000001 < access-control-allow-credentials: true
  0000001 < access-control-allow-origin: *
  0000001 < connection: keep-alive
  0000001 < content-length: 0
  0000001 < date: Fri, 06 Oct 2023 08:13:38 GMT
  0000001 < server: gunicorn/19.9.0
  0000001 < www-authenticate: Basic realm="Fake Realm"
  0000001 <
  """
  require Logger

  alias Req.Request

  def attach(request = %Request{}) do
    request
    |> Request.put_private(:log_id, System.unique_integer([:positive, :monotonic]))
    |> insert_request_step_before(:compress_body, {:log_request, &log_request/1})
    |> Request.prepend_response_steps(log_response_head: &log_response_head/1)
    |> insert_response_step_after(
      :decompress_body,
      {:log_response_body, &log_response_body/1}
    )
  end

  defp insert_request_step_before(request, name, step) do
    # request steps need two lists, see Request.append_request_step/2!
    %{request_steps: request_steps, current_request_steps: current_request_steps} = request
    index = Enum.find_index(request_steps, fn {x, _step} -> x == name end)
    request_steps = List.insert_at(request_steps, index, step)

    index = Enum.find_index(current_request_steps, fn x -> x == name end)
    {step_name, _func} = step
    current_request_steps = List.insert_at(current_request_steps, index, step_name)

    %{request | current_request_steps: current_request_steps, request_steps: request_steps}
  end

  defp insert_response_step_after(request, name, step) do
    steps = request.response_steps
    index = Enum.find_index(steps, fn {x, _step} -> x == name end)
    steps = List.insert_at(steps, index + 1, step)
    %{request | response_steps: steps}
  end

  defp log_request(request) do
    prefix = [log_id(request), " > "]
    log_request(prefix, request)
    log_headers(prefix, request.headers)
    log_body(prefix, request.body)
    request
  end

  defp log_response_head({request, response}) do
    prefix = [log_id(request), " < "]
    log_status(prefix, response.status)
    log_headers(prefix, response.headers)

    {request, response}
  end

  defp log_response_body({request, response}) do
    prefix = [log_id(request), " < "]
    log_body(prefix, response.body)

    {request, response}
  end

  defp log_id(request) do
    :io_lib.format("~7..0B", [Request.get_private(request, :log_id, 0)])
  end

  # This clause matches "not empty"
  # outgoing body on request is nil | binary | iolist, empty is nil.
  # incoming body on response is binary, empty is "".
  # Now, we have several body for an outgoing request that maps to 0 bytes to http : "", [], [""], ...
  # So I opt for always a line for http body.
  defp log_body(prefix, body) do
    Logger.debug([prefix, body || ""])
  end

  defp log_headers(prefix, headers) do
    for {name, value} <- headers do
      Logger.debug([prefix, name, ": ", value])
    end
  end

  defp log_status(prefix, status) do
    Logger.debug([prefix, to_string(status)])
  end

  defp log_request(prefix, request) do
    Logger.debug([
      prefix,
      to_string(request.method) |> String.upcase(),
      " ",
      URI.to_string(request.url)
    ])
  end
end

[venkatd]

Thanks a lot!

[krainboltgreene]

Wow this would be so incredibly useful, I've always want this kind of functionality in every http library, cool to see Req plan to have it.