Elixir / Phoenix / Ecto: How to customize SQL query log format?

Question

In my Phoenix/Ecto apps, when I set log level to :debug, I see helpful log entries for each SQL query issued by Ecto, like this:

[debug] QUERY OK source="users" db=1.9ms
SELECT u0."id", u0."full_name", u0."email", u0."uuid", u0."auth0_uid", u0."last_signed_in_at", u0."inserted_at", u0."updated_at" FROM "users" AS u0 WHERE (u0."id" = $1) LIMIT 1 [1]
[debug] QUERY OK source="projects" db=11.8ms
SELECT p0."id", p0."name", p0."uuid", p0."settings", p0."inserted_at", p0."updated_at" FROM "projects" AS p0 WHERE (p0."uuid" = $1) LIMIT 1 ["7qDjSk"]
[debug] QUERY OK source="project_admin_joins" db=1.9ms
SELECT p0."id", p0."project_id", p0."admin_id", p0."inserted_at", p0."updated_at", p0."project_id" FROM "project_admin_joins" AS p0 WHERE (p0."project_id" = $1) ORDER BY p0."project_id" [2]

But I'd love to tweak a couple things about this format:

Each sql query produces two lines of log output. It's important to me to have all this info on a single line, because that makes it much easier to find events in log management services like Papertrail.
Ideally I'd like to strip out the quotes around the field names so the query is easier to visually scan.

How can I customize the format of the Ecto sql query logs?

Topher Hunt Topher Hunt · Accepted Answer · 2019-06-14T15:40:11

It looks like there's no such thing as customizing Ecto's logging format; instead I needed to disable the built-in logging and write my own logging function. But this works very differently in Ecto v2 versus Ecto v3.

Ecto v2

In config.exs, configure MyApp.Repo to use a new custom logger function. That function can live wherever, but in my case I've put it in MyApp.Repo.log_query/2:

config :my_app, MyApp.Repo,
  # ...
  loggers: [{MyApp.Repo, :log_query, []}]

In lib/my_app/repo.ex, define the log_query function: (note: in my case I've hard-coded the :debug log level.)

  ...
  require Logger

  # Inspired by https://github.com/elixir-ecto/ecto/blob/v2.2.11/lib/ecto/log_entry.ex
  def log_query(entry) do
    Logger.log(:debug, fn ->
      {ok, _} = entry.result
      source = inspect(entry.source)
      time_us = System.convert_time_unit(entry.query_time, :native, :microsecond)
      time_ms = div(time_us, 100) / 10
      # Strip out unnecessary quotes from the query for readability
      query = Regex.replace(~r/(\d\.)"([^"]+)"/, entry.query, "\\1\\2")
      params = inspect(entry.params, charlists: false)

      "SQL query: #{ok} source=#{source} db=#{time_ms}ms   #{query}   params=#{params}"
    end)
  end

That's it! Make sure your log level is set appropriately, restart your app, and you should see all Ecto queries logged in this new format instead of the old one.

Ecto v3

Ecto v3 encourages you to use telemetry events instead of that nasty old config stuff.

In lib/my_app/application.ex MyApp.Application.start/2, you need to set up the telemetry event. Add this snippet just before the Supervisor.start_link/2 call:

    # Subscribe to Ecto queries for logging
    # See https://hexdocs.pm/ecto/Ecto.Repo.html#module-telemetry-events
    # and https://github.com/beam-telemetry/telemetry
    handler = &MyApp.Telemetry.handle_event/4
    :ok = :telemetry.attach("my_app-ecto", [:my_app, :repo, :query], handler, %{})

Then define your Telemetry module which for now will only have this one event handler. I saved mine in lib/my_app/telemetry.ex:

defmodule MyApp.Telemetry do
  require Logger

  # Thanks to https://hexdocs.pm/ecto/Ecto.Repo.html#module-telemetry-events
  def handle_event([:my_app, :repo, :query], measurements, metadata, _config) do
    Logger.log(:debug, fn ->
      {ok, _} = metadata.result
      source = inspect(metadata.source)
      time = div(measurements.query_time, 100_000) / 10
      # Strip out unnecessary quotes from the query for readability
      query = Regex.replace(~r/(\d\.)"([^"]+)"/, metadata.query, "\\1\\2")
      params = inspect(metadata.params, charlists: false)

      "SQL query: #{ok} source=#{source} db=#{time}ms   #{query}   params=#{params}"
    end)
  end
end

In config/config.exs, configure MyApp.Repo to disable the standard Ecto logging:

config :my_app, MyApp.Repo,
  # ...
  log: false

That's it! Make sure your log level is set appropriately, restart your app, and you should see all Ecto queries logged in this new format instead of the old one.

Elixir / Phoenix / Ecto: How to customize SQL query log format?

1 Answers

Ecto v2

Ecto v3