Structured Logging for LiveView (handle_params and channels)

I am on my phone, so I will be able to respons only to some of these right now.

About 2. the reason is probably because Phoenix decided to log on Telemetry messages instead of using Logger directly, which caused that weird behaviour. However someone with better Phoenix logging experience should tell you more. Personally I think that this is wrong approach (as this makes the stuff like location metadata useless), but I see that it is pretty common in Phoenix and Ecto.

About 3. you cannot really do so with Elixir Backends. You could “hack around” with translators, but that would be hacking instead of looking for a solution. “Real” solution would be usage of Erlang Handlers with Formatters, but using these from Elixir isn’t really straightforward, so this may require a little bit more knowledge (however it will came with a great power).

Hey, thanks for your work on logging.

So for 2, I found the following to disable Phoenix logs completely:
config :phoenix, :logger, false
Not sure if it’s a good idea, but it works.

Regarding 3 - can you point me in the right direction? I’m considering patching the logster library right now or maybe using flatlog.

Glad you already answered the question about that

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, []}})

I had a poke around at this, but I think writing your own handler is a pretty big undertaking, while also throwing out a what logger gives you for free (afaik you would have to disable logger else I was getting double logs).

You also have to filter to the elixir domain or handle a bunch of erlang reports. If you have disabled Logger and only filter for elixir, you might fall in some visibility holes.

You also lose stuff like coloured output and the single line exceptions can be a pain with stuff like liveview where you don’t see them rendered. This doesn’t really matter except that if you’re writing your own logger, you probably want to be dang sure it works and so running it in dev is a good way to battle test it, so you do actually notice those missing things.

I may have misunderstood and perhaps it’s simpler to run the two side by side (just unset_handler for logger in the elixir domain?) or just hijack specific message signatures.

I did experiment with just enabling all metadata and writing a formatter to drop what I don’t want, but I am not sure I am that keen on it.

In the end I think the better option is having your modules return their keys explicitly and collating them into the normal allow list in config.

Logger does actually accept maps and keyword lists, but they get marked as “erlang reports”, which pass through some special formatting. Since we would be passing in an unknown report format, it lands in Kernel.inspect and such your formatter gets passed just the string.

Unfortunately, you can’t just ignore the inspect because the value is later passed into a truncation function. You can skip that if you set the truncate option to :infinity, which is probably ok.

I would open a PR with a fix but I am not really sure what it should look like.

Obviously you don’t want to just drop the report code, so you need a way to flag you want to skip it just for specific messages.

You could flag that in the metadata (mixing domains here ) but probably the better choice is letting Logger.log flag on the way down whether to coerce types or not (since it’s in elixir land, unlikely a real “erlang report” has spawned from there, probably?).

But, that’s potentially a breaking change if people expect it to auto coerce the types.

Maybe a auto_coerce: true option default for logger so that you can elect into passing non-strings to your custom formatter.

I do not know why you say so. It is pretty simple, especially as you do not really need to implement whole backend, just the formatter you want.

defmodule MyFormatter do
  def format(%{level: level, msg: msg, meta: meta}, %{format: format}) do
    {:ok, report_cb} =
      with :error <- Map.fetch(meta, :report_cb),
           :error <- Map.fetch(meta, :report_cb),
           do: {:ok, &:logger.format_report/1}

    msg = format_msg(msg, report_cb)
    time = :calendar.system_time_to_rfc3339(meta.time, unit: :millisecond)
    data = Map.merge(meta, %{
      msg: msg,
      time: time,
      level: Atom.to_string(level)
    })
    do_format(format, data, [])
  end

  defp do_format([], _data, acc), do: :lists.reverse(acc)

  defp do_format([str | rest], level, data, acc) when is_binary(str) do
    do_format(rest, data, [str | acc])
  end

  defp do_format([:mfa | rest], data, acc) do
    text =
      case data do
        %{mfa: {module, function, arity}} ->
          [inspect(module), $., Atom.to_string(function), $/, Integer.to_string(arity)]
        _ -> []
      end
    do_format(rest, msg, time, meta, [text | acc])
  end

  defp do_format([path | rest], msg, time, meta, acc)
    when is_atom(path)
    when is_list(path) and is_atom(hd(path))
  do
    value = get(meta, List.wrap(path), [])
    do_format(rest, msg, time, meta, [stringify(value) | acc])
  end

  defp do_format([{path, default} | rest], msg, time, meta, acc) do
    value = get(meta, path, default)
    do_format(rest, msg, meta, [stringify(value) | acc])
  end

  defp get(value, [], default), do: value

  defp get(map, [key | rest], default) do
    case map do
      %{key => next} -> get(next, rest, default)
      _ -> default
    end
  end

  def stringify(value) when is_binary(value), do: value
  def stringify(value) do
    case String.Chars.impl_for(value) do
      nil -> inspect(value)
      module -> module.to_string(value)
    end
  end

  defp format_msg({:string, string}, _), do: string

  defp format_msg({:report, report}, report_cb) when is_function(report_cb, 1) do
    format_msg(report_cb.(report), report_cb)
  end

  defp format_msg({:report, report}, report_cb) when is_function(report_cb, 2) do
    report_cb.(report, %{})
  end

  defp format_msg({format, terms}, _report_cb) do
    # Here we use non-public API - https://github.com/elixir-lang/elixir/issues/10882
    format
    |> Logger.Utils.scan_inspect(terms, :infinity)
    |> :io_lib.build_text()
  end
end

Now you can use it like:

:logger.add_handler(:my_logger, :logger_std_h, %{formatter: {MyFormatter, %{format: [:time, " [", :level, "] ", :msg]}}})

Of course this could be improved even more, but it gives the initial view on how to implement the simple formatter in Elixir.

You can wrap other formatter with stuff that will add colouring.

I would need to check, because these two shouldn’t be related to each other.

You can run as many loggers beside each other as you like. You aren’t limited there (in contrast to many Elixir backends that allow only one instance of themselves to be installed at the same time). For filtering on domain you can use logger_filters.

The problem is that message get stringified before it reaches any backend. Making it passthrough would require a lot of boilerplate and checking for support. I think that sooner Elixir will deprecate the backends than implementing such magic behaviour where some handlers can get structured logs and some will get them stringified. The only problem there right now is that there is no built-in overload protection in Erlang handlers, so we cannot deprecate them right now, as writing Erlang handlers in overload-safe way is non-obvious.

I appreciate the code. I had to tweak some parts to make it work for anyone else coming through (just some mixed up params, time unit and adding a new line):

defmodule HaulethLogger do
  def format(%{level: level, msg: msg, meta: meta}, %{format: format}) do
    {:ok, report_cb} =
      with :error <- Map.fetch(meta, :report_cb),
           :error <- Map.fetch(meta, :report_cb),
           do: {:ok, &:logger.format_report/1}

    msg = format_msg(msg, report_cb)
    time = :calendar.system_time_to_rfc3339(meta.time, unit: :microsecond)
    data = Map.merge(meta, %{
      msg: msg,
      time: time,
      level: Atom.to_string(level)
    })
    [do_format(format, data, []) | ["\n"]]
  end

  defp do_format([], _data, acc), do: :lists.reverse(acc)

  defp do_format([str | rest], data, acc) when is_binary(str) do
    do_format(rest, data, [str | acc])
  end

  defp do_format([:mfa | rest], data, acc) do
    text =
      case data do
        %{mfa: {module, function, arity}} ->
          [inspect(module), ".", Atom.to_string(function), "/", Integer.to_string(arity)]
        _ -> []
      end
    do_format(rest, data, [text | acc])
  end

  defp do_format([path | rest], data, acc)
    when is_atom(path)
    when is_list(path) and is_atom(hd(path))
  do
    value = get(data, List.wrap(path), [])
    do_format(rest, data, [stringify(value) | acc])
  end

  defp do_format([{path, default} | rest], data, acc) do
    value = get(data, path, default)
    do_format(rest, data, [stringify(value) | acc])
  end

  defp get(value, [], _default), do: value

  defp get(map, [key | rest], default) do
    case map do
      %{^key => next} -> get(next, rest, default)
      _ -> default
    end
  end

  def stringify(value) when is_binary(value), do: value
  def stringify(value) do
    case String.Chars.impl_for(value) do
      nil -> inspect(value)
      module -> module.to_string(value)
    end
  end

  defp format_msg({:string, string}, _), do: string

  defp format_msg({:report, report}, report_cb) when is_function(report_cb, 1) do
    format_msg(report_cb.(report), report_cb)
  end

  defp format_msg({:report, report}, report_cb) when is_function(report_cb, 2) do
    report_cb.(report, %{})
  end

  defp format_msg({format, terms}, _report_cb) do
    # Here we use non-public API - https://github.com/elixir-lang/elixir/issues/10882
    format
    |> Logger.Utils.scan_inspect(terms, :infinity)
    |> :io_lib.build_text()
  end
end

Yeah after thinking about tonight, I was mixing terminology between the logger and the console backend. What I really want is some way to let my formatter capture those {:report...} messages that get sent to the handler, so they could translate them into strings for the back end…

# logfmt_translator.ex
defmodule LogfmtTranslator do

  # only match a specific format report
  def translate(_min_level, _level, :report, {:logger, data}) do
    case do_translate(data) do
      {:ok, translated} ->
        {:ok, translated}
      :error ->
        # could not translate so pass onto any other translators
        :none
    end
  end

  def translate(_min_level, _level, _kind, _message) do
    # we have no other translators, so pass out
    :none
  end

  # maps are fine as long as they are flat,
  # you may want to rescue into inspect() here or flatten maps or ...
  # probably smart because you don't want your logger failing
  defp do_translate(map) when is_map(map) do
    {:ok, Logfmt.encode(map)}
  end

  # keyword lists are ok, normal lists are un-translatable
  defp do_translate(list) when is_list(list) do
    case Keyword.keyword?(list) do
      true -> {:ok, Logfmt.encode(list)}
      false -> :error
    end
  end

  # any other type is untranslatable
  defp do_translate(_), do: :error
end

# application.ex
# I do this in Application/start...
Logger.add_translator({LogfmtTranslator, :translate})

Logger.warning(
  tag: "cool_app.service.payments.cc_failure",
  trans_id: transaction.id,
  ...
)

def format(level, [_|_] = lines, time, metadata) do
  format(level, Enum.join(lines, "\\n"), time, metadata)
end

def format(level, "woozlewozzle" <> logfmted, time, metadata) do
  ["#{inspect(time)} #{inspect(level)} #{logfmted} #{inspect(metadata)}","\n"]
end

def format(level, message, time, metadata) do
  ["#{inspect(time)} #{inspect(level)} #{message} #{inspect(metadata)}","\n"]
end

So I’ve been using the following module in production for a few weeks now, took 3-4 hours to write after @hauleth showed me how to do it (thanks again!).

It’s been my to do list to push this to github, etc. but, well, this is better than no where at all. I prefer having the normal logger in dev though as the reports are much better formatted. I wanted to add an option for flat map also, but here is the json version.

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().

  ## 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_msg({:string, string}), do: %{"msg" => string}
  defp encode_msg({:report, report}), do: if is_map(report), do: report, else: Enum.into(report, %{})
  defp encode_msg({format, terms}), do: %{"msg" => (format |> Logger.Utils.scan_inspect(terms, :infinity) |> :io_lib.build_text()) }
  defp encode_meta(%{mfa: {m, f, a}}), do: %{mfa: "#{inspect(m)}.#{f}/#{a}"}

  # 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

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