lib/ecto/logger.ex

defmodule ExJsonLogger.Ecto.Logger do
  @moduledoc """
  An Ecto Logger replacement which captures and logs `Ecto.LogEntry` attributes through metadata.

  Logger Metadata available:
   * query - the query as string;
   * query_params - the query parameters as string;
   * query_time - the time spent executing the query in milliseconds;
   * decode_time - the time spent decoding the result in milliseconds;
   * queue_time - the time spent to check the connection out in milliseconds;

  Metadata is filtered by default so keys will need to be whitelisted.

  ## Usage

  Add `ExJsonLogger.Ecto.Logger` to the Repo's configuration under the `:loggers` key.

      config :sample, Sample.Repo,
        adapter: Ecto.Adapters.MySQL,
        username: "root",
        password: "",
        database: "sample_dev",
        hostname: "localhost",
        pool_size: 10,
        loggers: [{ExJsonLogger.Ecto.Logger, :log, []}]
  """

  require Logger

  @spec log(Ecto.LogEntry.t(), Logger.level()) :: Ecto.LogEntry.t()
  def log(entry, level \\ :debug) do
    %{
      query_time: raw_query_time,
      decode_time: raw_decode_time,
      queue_time: raw_queue_time,
      query: query,
      params: query_params
    } = entry

    times =
      [query_time, decode_time, queue_time] =
      Enum.map([raw_query_time, raw_decode_time, raw_queue_time], &to_ms/1)

    duration =
      times
      |> Enum.sum()
      |> Float.round(3)

    metadata =
      []
      |> Keyword.put(:db_duration, duration)
      |> Keyword.put(:decode_time, decode_time)
      |> Keyword.put(:query_time, query_time)
      |> Keyword.put(:queue_time, queue_time)
      |> Keyword.put(:query, query)
      |> Keyword.put(:query_params, inspect(query_params, charlists: false))

    Logger.log(level, fn -> {"", metadata} end)

    entry
  end

  defp to_ms(nil), do: 0.0

  defp to_ms(time) when is_integer(time) do
    # divide to keep decimal precision
    time
    |> System.convert_time_unit(:native, :microsecond)
    |> Kernel./(1000)
    |> Float.round(3)
  end
end