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"
}
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 ->
[
%{
level: "error",
message: "could not format json message",
logger_data: %{
exception: inspect(e),
level: inspect(level),
ts: inspect(ts),
message: inspect(message),
metadata: inspect(metadata)
}
}
|> Jason.encode!(),
"\n"
]
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`
- `:gl`
- `:crash_reason`
- `:initial_call`
- `:registered_name`
- `:domain`
- `:ancestors`
- `:callers`
Followings metadata will be removed:
- `:mfa`: see `:module` and `:funtion`
- `:report_cb`
## 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]
}
iex> MetadataLogger.log_to_map(
...> :info,
...> %{hello: :world},
...> {{2019, 11, 22}, {12, 23, 45, 678}},
...> []
...> )
%{
level: :info,
message: %{hello: :world},
metadata: %{},
timestamp: ~N[2019-11-22 12:23:45.000678]
}
iex> MetadataLogger.log_to_map(
...> :info,
...> [foo: 1, foo: 2],
...> {{2019, 11, 22}, {12, 23, 45, 678}},
...> []
...> )
%{
level: :info,
message: %{foo: 2},
metadata: %{},
timestamp: ~N[2019-11-22 12:23:45.000678]
}
"""
@spec log_to_map(
Logger.level(),
Logger.message() | Logger.report(),
Logger.Formatter.time(),
keyword
) ::
map()
def log_to_map(level, message, ts, 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),
{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))
|> put_val(:domain, domain)
|> put_val(:ancestors, nil_or_inspect_list(ancestors))
|> put_val(:callers, nil_or_inspect_list(callers))
end
|> Map.put(:level, level)
|> Map.put(:message, transform_message(message))
|> Map.put(:timestamp, transform_timestamp(ts))
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_message(%_{} = m), do: to_string(m)
defp transform_message(m) when is_map(m), do: m
defp transform_message([{_k, _v} | _t] = m), do: Enum.into(m, %{})
defp transform_message(m) when is_list(m), do: IO.iodata_to_binary(m)
defp transform_message(m), do: to_string(m)
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
