metadata_logger

defmodule MetadataLogger do
  @moduledoc """
  Logging with metadata.

  ## Configuration

  ```elixir
  config :logger, :console,
    level: :debug,
    format: {MetadataLogger, :format},
    colors: [enabled: false],
    metadata: :all,
    truncate: :infinity,
    utc_log: true
  ```
  """

  @doc """
  Formatter function to print message and metadata in a single-line json.

  Make sure all metadata except known metadata encodable by `Jason.encode_to_iodata!/2`.
  See `log_to_map/4` for transformation on known metadata.

  It removes `:function`, `:file`, and `:line` from the log.

  ## Examples

      iex> MetadataLogger.format(
      ...>   :info,
      ...>   ["hello", " ", "world"],
      ...>   {{2019, 11, 22}, {12, 23, 45, 678}},
      ...>   function: "hello/1",
      ...>   file: "/my/file.ex",
      ...>   line: 11,
      ...>   foo: :bar
      ...> ) |> Jason.decode!()
      %{
        "level" => "info",
        "message" => "hello world",
        "metadata" => %{"foo" => "bar"},
        "timestamp" => "2019-11-22T12:23:45.000678"
      }

  """
  @spec format(Logger.level(), Logger.message(), Logger.Formatter.time(), keyword) ::
          IO.chardata()
  def format(level, message, ts, metadata) do
    map = log_to_map(level, message, ts, metadata)

    [
      map
      |> scrub()
      |> Jason.encode_to_iodata!(map),
      "\n"
    ]
  rescue
    e -> "could not format: #{inspect(e)} - #{inspect({level, ts, message, metadata})}"
  end

  @doc """
  Get a map from log formatter arguments.

  It converts `t:Logger.Formatter.time/0` into `NaiveDateTime` so it is recommended to configure logger to use UTC by setting `:utc_log` to `true`.

  It converts metadata keyword into map using `Enum.into/2` therefore duplicated keys will be removed.

  It moves following known metadata to the top level. See [Logger Metadata](https://hexdocs.pm/logger/Logger.html#module-metadata) for details.

  - `:application`
  - `:module`
  - `:function`
  - `:file`
  - `:line`
  - `:pid`
  - `:crash_reason`
  - `:initial_call`
  - `:registered_name`

  ## Examples

      iex> MetadataLogger.log_to_map(
      ...>   :info,
      ...>   ["hello", " ", "world"],
      ...>   {{2019, 11, 22}, {12, 23, 45, 678}},
      ...>   foo: :bar
      ...> )
      %{
        level: :info,
        message: "hello world",
        metadata: %{foo: :bar},
        timestamp: ~N[2019-11-22 12:23:45.000678]
      }

  """
  @spec log_to_map(Logger.level(), Logger.message(), Logger.Formatter.time(), keyword) ::
          map()
  def log_to_map(level, message, ts, metadata) do
    with m <- Enum.into(metadata, %{}),
         m <- Map.drop(m, [:mfa, :report_cb]),
         {app, m} <- Map.pop(m, :application),
         {module, m} <- Map.pop(m, :module),
         {function, m} <- Map.pop(m, :function),
         {file, m} <- Map.pop(m, :file),
         {line, m} <- Map.pop(m, :line),
         {pid, m} <- Map.pop(m, :pid),
         {gl, m} <- Map.pop(m, :gl),
         {crash_reason, m} <- Map.pop(m, :crash_reason),
         {initial_call, m} <- Map.pop(m, :initial_call),
         {registered_name, m} <- Map.pop(m, :registered_name) do
      %{metadata: m}
      |> put_val(:app, app)
      |> put_val(:module, module)
      |> put_val(:function, function)
      |> put_val(:file, file)
      |> put_val(:line, line)
      |> put_val(:pid, nil_or_inspect(pid))
      |> put_val(:gl, nil_or_inspect(gl))
      |> put_val(:crash_reason, nil_or_inspect(crash_reason))
      |> put_val(:initial_call, nil_or_inspect(initial_call))
      |> put_val(:registered_name, nil_or_inspect(registered_name))
    end
    |> Map.put(:timestamp, transform_timestamp(ts))
    |> Map.put(:level, level)
    |> Map.put(:message, to_string(message))
  end

  defp nil_or_inspect(nil), do: nil
  defp nil_or_inspect(val), do: inspect(val)

  defp put_val(map, _key, nil), do: map
  defp put_val(map, key, val), do: Map.put(map, key, val)

  defp transform_timestamp({{y, month, d}, {h, minutes, s, mil}}) do
    {:ok, dt} = NaiveDateTime.new(y, month, d, h, minutes, s, mil)
    dt
  end

  defp scrub(map) do
    map
    |> Map.delete(:function)
    |> Map.delete(:file)
    |> Map.delete(:line)
  end
end