Elixir / Phoenix: How to customize HTTP request log format?

By default, my Phoenix apps log basic information about each HTTP request across ~ 5 lines of log output. As long as I've set my log level to :debug, I can see each request's method, path, controller & action, params, response code, and duration:

2019-06-14 16:05:35.099 [info] GET /manage/projects/7qDjSk
2019-06-14 16:05:35.103 [debug] Processing with RTLWeb.Manage.ProjectController.show/2
  Parameters: %{"project_uuid" => "7qDjSk"}
  Pipelines: [:browser, :require_login]
2019-06-14 16:05:35.116 [info] Sent 200 in 17ms

That's a great starting point. But I'd like to customize the app to log all of this info on one line, which is helpful eg. when sifting through large amounts of log output in a tool like Papertrail. In particular I'd like each request to show up in a format like this:

[PUT /manage/projects/74/prompts/290] params=%{"project_uuid" => "74", "prompt" => %{"html" => "<div>Test question 3</div>"}, "prompt_uuid" => "290"} user=38 (Topher Hunt) status=302 redirected_to=/manage/projects/74 duration=423ms

In the Phoenix.Controller docs I see I can configure the log level for the Phoenix controller logging, or disable it altogether, but I don't see a way to customize the format. How can I do this?

Solution

This isn't a matter of customizing output, rather it's a matter of 1) disabling the default request-related log statements (by detaching the relevant :telemetry handlers) then 2) adding a new plug to log the format I want.

Here's how I did it:

In lib/my_app_web/endpoint.ex, comment out the Plug.Telemetry plug.
If you find the default LiveView mount & Channel connection logs too noisy, you can also disable those by adding the following in application.ex just before Supervisor.start_link():

    :ok = :telemetry.detach({Phoenix.Logger, [:phoenix, :socket_connected]})
    :ok = :telemetry.detach({Phoenix.Logger, [:phoenix, :channel_joined]})
    :ok = :telemetry.detach({Phoenix.Logger, [:phoenix, :router_dispatch, :start]})

In lib/my_app_web/endpoint.ex, add this custom plug just before Plug.Session:

# One-line request logging. Must come before the session & router plugs.
plug MyAppWeb.RequestLogger

Finally, add lib/my_app_web/plugs/request_logger.ex. (Adjust the details accordingly; this implementation assumes the logged-in user struct is stored in conn.assigns.current_user):

# One-line full request logging inspired by Plug.Logger.
# See https://github.com/elixir-plug/plug/blob/v1.8.0/lib/plug/logger.ex
# Need to restart the server after updating this file.
defmodule MyAppWeb.RequestLogger do
  require Logger

  @behaviour Plug

  def init(opts), do: opts

  def call(conn, _opts) do
    start_time = System.monotonic_time()

    Plug.Conn.register_before_send(conn, fn(conn) ->
      # We don't want passwords etc. being logged
      params = inspect(Phoenix.Logger.filter_values(conn.params))

      # Log any important session data eg. logged-in user
      user = conn.assigns[:current_user]
      user_string = if user, do: "#{user.id} (#{user.name})", else: "(none)"

      # Note redirect, if any
      redirect = Plug.Conn.get_resp_header(conn, "location")
      redirect_string = if redirect != [], do: " redirected_to=#{redirect}", else: ""

      # Calculate time taken (in ms for consistency)
      stop_time = System.monotonic_time()
      time_us = System.convert_time_unit(stop_time - start_time, :native, :microsecond)
      time_ms = div(time_us, 100) / 10

      Logger.log(:info,
        "■ method=#{conn.method} path=#{conn.request_path} params=#{params} "<>
        "user=#{user_string} status=#{conn.status}#{redirect_string} duration=#{time_ms}ms"
      )

      conn
    end)
  end
end

Restart your server, and you should now see just one log line per request, formatted like this:

2019-06-09 18:18:51.410 [info] ■ [PUT /manage/projects/7qDjSk/prompts/3tUrF9] params=%{"project_uuid" => "7qDjSk", "prompt" => %{"html" => "<div>Test question 3</div>"}, "prompt_uuid" => "3tUrF9"} user=1 (Topher Hunt) status=302 redirected_to=/manage/projects/7qDjSk duration=21ms

(Note: Another, more best-practice approach would be to :telemetry.attach to the [:phoenix, :router_dispatch, :stop] event that Phoenix is already emitting. This provides all the data we'd need; see the Phoenix.Endpoint docs for more detail.)

Useful references: