Logging raw request

[emarthinsen]

Is there a way to log the raw request sent through the various adapters? I want to inspect exactly what is being sent to the various AI providers.

[serpent213]

Just had the same issue and came up with this for logging:

defmodule Senegal.Test.FinchLogger do
  require Logger

  @log_dir "tmp/finch_logs"

  def attach do
    # Ensure log directory exists
    File.mkdir_p!(@log_dir)

    # Only attach to the request stop event which has all the info we need
    :telemetry.attach(
      "finch-test-logger",
      [:finch, :request, :stop],
      &__MODULE__.handle_event/4,
      nil
    )

    Logger.info("Finch request logging enabled. Logs will be written to: #{@log_dir}")
  end

  def detach do
    :telemetry.detach("finch-test-logger")
  end

  def handle_event([:finch, :request, :stop], measurements, metadata, _config) do
    request = metadata[:request]
    result = metadata[:result]
    timestamp = DateTime.utc_now() |> DateTime.to_iso8601()

    request_body = format_body(request.body)
    response_content = format_result(result)

    log_content = """
    ============ Finch Request [#{timestamp}] ============
    Method: #{request.method}
    URL: #{request.scheme}://#{request.host}:#{request.port}#{request.path}

    Headers:
    #{format_headers(request.headers)}

    Body:
    #{request_body}

    ============ Finch Response (#{format_duration(measurements[:duration])}) ============
    #{response_content}
    """

    # Always write to file
    filename = "finch_#{timestamp |> String.replace(":", "-")}.log"
    filepath = Path.join(@log_dir, filename)
    File.write!(filepath, log_content)

    Logger.info("""
    Finch request logged to: #{filepath}
    Summary - #{request.method} #{request.scheme}://#{request.host}:#{request.port}#{request.path} -> #{get_status(result)} (#{format_duration(measurements[:duration])})
    """)
  end

  defp format_result({:ok, %{status: status, headers: headers, body: body}}) do
    # Check for gzip encoding
    body =
      case is_gzipped?(headers) do
        true -> gunzip_body(body)
        false -> body
      end

    """
    Status: #{status}

    Headers:
    #{format_headers(headers)}

    Body:
    #{format_body(body)}
    """
  end

  defp format_result({:error, reason}) do
    "Error: #{inspect(reason)}"
  end

  defp format_result(other) do
    "Result: #{inspect(other, pretty: true)}"
  end

  defp format_headers(headers) do
    headers
    |> Enum.map(fn {key, value} -> "  #{key}: #{value}" end)
    |> Enum.join("\n")
  end

  defp format_body(body) when is_binary(body) do
    case Jason.decode(body) do
      {:ok, json} ->
        json
        |> Jason.encode!(pretty: true)
        |> fix_escape_sequences()

      {:error, _} ->
        # If it's not JSON, just fix escape sequences
        fix_escape_sequences(body)
    end
  end

  defp format_body(body) when is_list(body) do
    # Convert IO list to binary first
    body
    |> IO.iodata_to_binary()
    |> format_body()
  end

  defp format_body(body), do: inspect(body, pretty: true)

  defp fix_escape_sequences(text) do
    text
    # |> String.replace("\\n", "\n")
    # |> String.replace("\\t", "\t")
    # |> String.replace("\\\"", "\"")
    # |> String.replace("\\'", "'")
  end

  defp is_gzipped?(headers) do
    Enum.any?(headers, fn
      {"content-encoding", encoding} -> String.contains?(encoding, "gzip")
      _ -> false
    end)
  end

  defp gunzip_body(body) do
    try do
      :zlib.gunzip(body)
    rescue
      _ -> body
    end
  end

  defp get_status({:ok, %{status: status}}), do: status
  defp get_status({:error, _}), do: "error"
  defp get_status(_), do: "unknown"

  defp format_duration(nil), do: "N/A"

  defp format_duration(duration) do
    ms = System.convert_time_unit(duration, :native, :millisecond)
    "#{ms}ms"
  end
end