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://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
