Updated logger @PaintingWithCode . FYI, no stacktraces atm.

defmodule StructuredLogger do
  @moduledoc """
  StructuredLogger formats any incoming messages into JSON.

  The key difference between this logger and others is that it uses erlang handlers instead of elixir backends.
  Because the Elixir Backend interface for logging always returns the message as binary data, it is not
  possible to format it so that it can be decoded in a single pass in 1.11.4. With this logger, the output
  can be fully decoded into the appropriate types/terms.

  As it can parse both the message and the metadata, this formatter will merge the two into a relatively
  flat structure. For instance, the mfa, ip, user_id, and guid are from metadata, while the rest are from
  the plug request. This makes it easier to write queries on the backend system.

      {"duration":126.472,"guid":"03de7c92-cdbf-4f67-ad10-6abd51ef634c","headers":{},"ip":"1.2.3.4","level":"info",
      "method":"GET","mfa":"StructuredLogger.Plugs.Logger.call/2","params":{},"path":"/","pid":"#PID<0.16365.0>",
      "request_id":"Fm5q11B9tgEmrLEAAZGB","status":200,"time":"2021-03-21T17:13:09.400033Z","user_id":8}

  Note that in development where you might want to see a well-formatted stacktrace of a 500 error or exception,
  you might want to continue using Logger for the console. Any exceptions will be put into a JSON format of
  {"level" => level, "metadata" => metadata, "msg" => report}

  ## Installation
  In the MyApp.Application.start/2, add the log handler for the formatter. Note that you may want to remove
  the Logger to avoid double logging.

      :logger.add_handler(:structured_logger, :logger_std_h, %{formatter: {StructuredLogger.FormatterJson, []}, level: :info})
      :logger.remove_handler(Logger)

  ### Phoenix and Plug

  To use it, just plug it into the desired module.

      plug StructuredLogger.Plugs.Logger, log: :debug

  For Phoenix applications, replace `Plug.Logger` with `StructuredLogger.Plugs.Logger` in the `endpoint.ex` file:

      # plug Plug.Logger
      plug StructuredLogger.Plugs.Logger,
        excludes: [:state]

  ### Logging

  Like normal, just use Logger.log. Maps and Keyword lists are supported.

      Logger.log(:info, %{"params" => %{"a" => "b"}, "duration" => 10})

  ### Using metadata

  Metadata such as ip address can be added to any request.

  For Phoenix, the easiest way to do so is to add it in your pipeline.

      defp logger_metadata(conn, _) do
        user_id = get_session(conn, :user_id)
        guid = get_session(conn, :guid)
        ip = get_session(conn, :ip)
        ip = if is_tuple(ip), do: Tuple.to_list(ip) |> Enum.join("."), else: ip
        Logger.metadata(%{user_id: user_id, ip: ip, guid: guid})
        conn
      end

      pipeline :browser do
        plug :accepts, ["html"]
        plug :fetch_session
        plug :fetch_live_flash
        plug :protect_from_forgery
        ...
        plug :logger_metadata
      end

  For Phoenix Liveview, call Logger.metadata from the mount().

  ### Notes

  Phoenix.Router.NoRouteError may cause some exceptions being logged for 404's.
  Adding the folloing to scopes will render it as a 404.

      get "/:no_route", PageController, :page_404

  ## Credits

  https://github.com/elixir-metadata-logger/metadata_logger
  https://github.com/navinpeiris/logster
  https://forum.elixirforum.com/t/structured-logging-for-liveview-handle-params-and-channels/38333/5

  """

end

defmodule StructuredLogger.FormatterJson do
  require Logger

  @doc """
  Only for use with the erlang log handler.
  Any formatted exception reports with stacktraces that are normally shown on 500 errors are no longer available.
  The exceptions will be wrapped in the json formatter.
  """
  def format(%{level: level, msg: msg, meta: meta}, _config) do
    # If it doesn't encode, it is likely an exception being thrown with a weird report
    # https://github.com/elixir-lang/elixir/blob/a362e11e20b03b5ca7430ec1f6b4279baf892840/lib/logger/lib/logger/handler.ex#L229
    # To successfully format, we'd need to do something like:
    # defp encode_msg( {:report, %{label: label, report: report} = complete} ) when map_size(complete) == 2 do
    #   case Logger.Translator.translate(:debug, "unused", :report, {label, report}) do
    #   etc.
    # However, these are being encoded, not for display in dev, so not sure why we need to be too careful here.
    try do
      mfa =  encode_meta(meta)
      encoded_msg = encode_msg(msg)
      x = log_to_map(level, meta)
      |> Map.merge(mfa)
      |> Map.merge(encoded_msg)
      |> scrub
      [ Jason.encode_to_iodata!(x)  , "\n"]
    rescue
      _e ->
        # Give a full dump here
        rescue_data = %{"level" => level, "meta" => inspect(meta), "msg" => inspect(msg)}
        [ Jason.encode_to_iodata!(rescue_data)  , "\n"]
    end
  end

  defp encode_meta(%{mfa: {m, f, a}}), do: %{mfa: "#{inspect(m)}.#{f}/#{a}"}
  defp encode_meta(_meta), do: %{mfa: "unknown caller"}
  defp encode_msg({:string, string}), do: %{"msg" => string}
  defp encode_msg({:report, %{label: _label, report: _report} = msg}) do
    case Logger.Translator.translate(:error, :error, :report, msg) do
      {:ok, chardata, _metadata} -> %{"msg" => to_string(chardata)}
      {:ok, chardata} -> %{"msg" => to_string(chardata)}
      :skip -> %{}
      :none -> %{}
    end
  end

  defp encode_msg({:report, report}) do
    # x = Logger.Translator.translate(:info, :info, :report, report)
    cond do
      is_map(report) and map_size(report) > 2 and Map.keys(report) == [:args, :format, :label] -> 
        #IO.inspect  Logger.Translator.translate(:info, :info, :report, report)
        #IO.inspect %{"format" => to_string(report[:format]), "label" => report[:label]}
        # This line ensures we get crash reports
        %{"format" => to_string(report[:format]), "args" => report[:args]}
      is_map(report) ->
        report
      true ->
        Enum.into(report, %{})
    end
  end
  defp encode_msg({format, terms}), do: %{"msg" => (format |> Logger.Utils.scan_inspect(terms, :infinity) |> :io_lib.build_text()) }

  # https://github.com/elixir-metadata-logger/metadata_logger
  @spec log_to_map(Logger.level(), list[keyword]) :: map()
  def log_to_map(level, metadata) do
    with m <- Enum.into(metadata, %{}),
         m <- Map.drop(m, [:error_logger, :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),
         {ancestors, m} <- Map.pop(m, :ancestors),
         {callers, m} <- Map.pop(m, :callers),
         {crash_reason, m} <- Map.pop(m, :crash_reason),
         {initial_call, m} <- Map.pop(m, :initial_call),
         {domain, m} <- Map.pop(m, :domain),
         {time, m} <- Map.pop(m, :time),
         {registered_name, m} <- Map.pop(m, :registered_name) do

      m
      |> put_val(:app, app)
      |> put_val(:module, module)
      |> put_val(:function, function)
      |> put_val(:file, to_string(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))
      |> put_val(:domain, domain)
      |> put_val(:ancestors, nil_or_inspect_list(ancestors))
      |> put_val(:callers, nil_or_inspect_list(callers))
      |> put_val(:time, transform_timestamp(time))
    end
    |> Map.put(:level, level)
  end

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

  defp nil_or_inspect_list(nil), do: nil
  defp nil_or_inspect_list(val), do: Enum.map(val, &inspect/1)

  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)
    NaiveDateTime.to_iso8601(dt)
  end

  defp transform_timestamp(t) do
    DateTime.from_unix!(t, :microsecond)
    |> DateTime.to_iso8601
  end

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

defmodule StructuredLogger.Plugs.Logger do
  @moduledoc """
  The plug is based on Logster ( https://github.com/navinpeiris/logster ). Original module documentation follows with minor edits.

  A plug for logging request information in the format set in the handler:

      method=GET path=/articles/some-article format=html controller=HelloPhoenix.ArticleController action=show params={"id":"some-article"} status=200 duration=0.402 state=set

  To use it, just plug it into the desired module.

      plug StructuredLogger.Plugs.Logger, log: :debug

  For Phoenix applications, replace `Plug.Logger` with `StructuredLogger.Plugs.Logger` in the `endpoint.ex` file:

      # plug Plug.Logger
      plug StructuredLogger.Plugs.Logger,
        excludes: [:state]

  ## Options

    * `:log` - The log level at which this plug should log its request info.
      Default is `:info`.
    * `:renames` - Map of fields to rename, for example: `%{status: :mystatus}`.
    * `:excludes` - List of fields to exclude from the log, for example: `[:params]`.
  """

  require Logger
  alias Plug.Conn

  @default_filter_parameters ~w(password)
  @default_allowed_headers ~w()

  def init(opts) do
    opts
  end

  def call(conn, opts) do
    start_time = current_time()

    Conn.register_before_send(conn, fn conn ->
      Logger.log(log_level(conn, opts), fn ->
        #formatter = Keyword.get(opts, :formatter, Logster.StringFormatter)
        renames = Keyword.get(opts, :renames, %{})
        stop_time = current_time()
        duration = time_diff(start_time, stop_time)

        []
        |> put_field(:method, renames, conn.method)
        |> put_field(:path, renames, conn.request_path)
        |> Keyword.merge(formatted_phoenix_info(conn))
        |> put_field(:params, renames, get_params(conn))
        |> put_field(:status, renames, conn.status)
        |> put_field(:duration, renames, formatted_duration(duration))
        |> put_field(:state, renames, conn.state)
        |> Keyword.merge(
          headers(
            conn.req_headers,
            Application.get_env(:logster, :allowed_headers, @default_allowed_headers)
          )
        )
        |> exclude(Keyword.get(opts, :excludes, []))
      end)

      conn
    end)
  end

  defp put_field(keyword, default_key, renames, value) do
    Keyword.put(keyword, Map.get(renames, default_key, default_key), value)
  end

  defp headers(_, []), do: []

  defp headers(conn_headers, allowed_headers) do
    map =
      conn_headers
      |> Enum.filter(fn {k, _} -> Enum.member?(allowed_headers, k) end)
      |> Enum.into(%{}, fn {k, v} -> {k, v} end)

    [{:headers, map}]
  end

  defp exclude(keyword, excludes) do
    Keyword.drop(keyword, excludes)
  end

  defp current_time, do: :erlang.monotonic_time()

  defp time_diff(start, stop),
    do: (stop - start) |> :erlang.convert_time_unit(:native, :micro_seconds)

  defp formatted_duration(duration), do: duration / 1000

  defp formatted_phoenix_info(%{
         private: %{
           phoenix_format: format,
           phoenix_controller: controller,
           phoenix_action: action
         }
       }) do
    [
      {:format, format},
      {:controller, controller |> inspect},
      {:action, action |> Atom.to_string()}
    ]
  end

  defp formatted_phoenix_info(_), do: []

  defp get_params(%{params: _params = %Plug.Conn.Unfetched{}}), do: %{}

  defp get_params(%{params: params}) do
    params
    |> do_filter_params(
      Application.get_env(:logster, :filter_parameters, @default_filter_parameters)
    )
    |> do_format_values
  end

  def do_filter_params(%{__struct__: mod} = struct, params_to_filter) when is_atom(mod),
    do: do_filter_params(Map.from_struct(struct), params_to_filter)

  def do_filter_params(%{} = map, params_to_filter) do
    Enum.into(map, %{}, fn {k, v} ->
      if is_binary(k) && String.contains?(k, params_to_filter) do
        {k, "[FILTERED]"}
      else
        {k, do_filter_params(v, params_to_filter)}
      end
    end)
  end

  def do_filter_params([_ | _] = list, params_to_filter),
    do: Enum.map(list, &do_filter_params(&1, params_to_filter))

  def do_filter_params(other, _params_to_filter), do: other

  def do_format_values(%_{} = params), do: params |> Map.from_struct() |> do_format_values()

  def do_format_values(%{} = params), do: params |> Enum.into(%{}, &do_format_value/1)

  def do_format_value({key, value}) when is_binary(value) do
    if String.valid?(value) do
      {key, value}
    else
      {key, URI.encode(value)}
    end
  end

  def do_format_value(val), do: val

  defp log_level(%{private: %{logster_log_level: logster_log_level}}, _opts),
    do: logster_log_level

  defp log_level(_, opts), do: Keyword.get(opts, :log, :info)
end

I’ve spent some time now messing around with a bunch of libraries.

For posterity:

• flatlog - works reasonably well with 1.11.4 and calling :logger.logdirectly. Unfortunately, it flattens all the elixir structs to their root elements, meaning that something like params: %{"b_time" => ~N[2021-03-21 00:00:06] becomes params_b_time_year=2021 params_b_time_second=6 params_b_time_month=3 params_b_time_minute=0 params_b_time_microsecond={0,0}. Wraps exceptions nicely though.

• Ink - Dumps everything to js which is fine, but not in a single log msg. And since the msg is not broken out, we can’t really use it unless we do regexp on the other side. Did not test exceptions.
  {"guid":"03de7c92-cdbf-4f67-ad10-6abd51ef634c","hostname":"x230a","level":30,"msg":"Sent 200 in 214ms","name":"x","pid":32183,"time":"2021-03-20T18:35:18.017Z","user_id":8,"v":0}

• elixir-metadata-logger · GitHub - does what it can given the interface. It turns out that if you write a formatter, Logger gives you back the msg as a string. This means that this project formats all the metadata well, but not the actual msg. Did not test exceptions.

• Logster - closest to a functioning solution with the Plug installation and a custom log helper for liveview. There’s some funkiness with metadata when using json which can be easily patched. Now using the plug and the custom format for liveview is fine, but that means the log format for logger is simply $message. This means that the exceptions are not wrapped. Again, as what goes to the format function in a string, there’s not much to do about it unless you want to encode it, pass it along, decode it, manipulate it, and send out the full msg encoded again. Seems a bit cpu-intensive for a log. But it mostly works.

• Logfmt - I was hopeful for this library, but it does not parse something like
  iex> Logfmt.decode(~S(x={"foo":"bar"}))
%{":" => true, "bar" => true, "foo" => true, "x" => "{", "}" => true}

• Telemetry - I was thinking of hooking up from here instead, but then there’s no way to add any metadata.

It seems that there are three different steps:

1. A plug library to wrap the the Conn call and get a single line of information.
2. A helper to generate the correct information for LiveView.
3. A wrapper to format the exceptions correctly, but does not additionally wrap the items from 1 and 2. The erlang library did not like the elixir structs, so I’m not sure how effective it would be write a log library in erlang instead, but it appears the library has access to “msg” in the original form, not just a string. Is that the option you were indicating @hauleth ?

So I’m a bit flummoxed. Hopefully, I’m somehow wrong or missed an alternative/option?

Well, that is exactly in the name of flatlog

Yes, that was the option I was talking about. However it is not true that “erlang library did not like the elixir structs”, it is just that Erlang doesn’t know about Elixir structs at all. It is perfectly feasible for Erlang library to account Elixir structs or even use Elixir’s inspect/2 for formatting data.

It is also important to mention that nothing prevents you from writing formatter for Erlang Logger in Elixir. Simplest possible formatter would be:

defmodule MyFormatter do
  def format(%{level: level, msg: msg, meta: meta}, _config) do
    Jason.encode!(%{level: :level, msg: encode_msg(msg), meta: encode_meta(meta)})
  end

  defp encode_msg({:string, string}), do: string
  defp encode_msg({:report, report}), do: report
  defp encode_msg({format, terms}), do: format |> Logger.Utils.scan_inspect(terms, :infinity) |> :io_lib.build_text()

  def encode_meta(%{mfa: {m, f, a}}), do: %{mfa: "#{inspect(m)}.#{f}/#{a}")
end

It only encodes one metadata field, but you get an idea how to make it work.

After that you can use this encoder with handler of your choice, for example like:

:logger.add_handler(:my_log, :logger_std_h, %{formatter: {MyFormatter, []}})