defmodule Logster do
@external_resource readme = Path.join([__DIR__, "../README.md"])
@moduledoc readme
|> File.read!()
|> String.split("<!-- MDOC -->")
|> Enum.fetch!(1)
require Logger
@default_filter_parameters ~w(password)
# Taken from `Logger` module
@levels [:emergency, :alert, :critical, :error, :warning, :notice, :info, :debug]
@phoenix_handler_id {__MODULE__, :phoenix}
@doc """
Attaches a telemetry handler to the `:phoenix` event stream for logging.
Returns `:ok`.
"""
@spec attach_phoenix_logger :: :ok
def attach_phoenix_logger do
events = [
[:phoenix, :endpoint, :stop],
[:phoenix, :socket_connected],
[:phoenix, :channel_joined],
[:phoenix, :channel_handled_in]
]
:telemetry.attach_many(
@phoenix_handler_id,
events,
&__MODULE__.handle_phoenix_event/4,
:ok
)
end
@doc """
Detaches logster's telemetry handler from the `:phoenix` event stream.
Returns `:ok`.
"""
@spec detach_phoenix_logger :: :ok
def detach_phoenix_logger, do: :telemetry.detach(@phoenix_handler_id)
def levels, do: @levels
for level <- @levels do
@doc """
Logs a #{level} message. See `Logster.log/3` for more information.
Returns `:ok`.
"""
@spec unquote(level)(message :: Logger.message(), metadata :: Logger.metadata()) :: :ok
def unquote(level)(fields_or_message_or_func, metadata \\ [])
def unquote(level)(func, metadata) when is_function(func),
do: Logger.unquote(level)(fn -> formatter().format(func.()) end, metadata)
def unquote(level)(fields_or_message, metadata),
do: Logger.unquote(level)(fn -> formatter().format(fields_or_message) end, metadata)
end
@doc """
Logs a message with the given `level`.
If given an enumerable, the enumerable will be formatted using the configured formatter.
Returns `:ok`.
Using `debug/2`, `info/2`, `notice/2`, `warning/2`, `error/2`, `critical/2`, `alert/2`,
and `emergency/2` are preferred over this function as they can automatically eliminate
the call to `Logger` altogether at compile time if desired
(see the documentation for the `Logger` module).
## Example
```
Logster.log(:info, service: "payment-processor", event: "start-processing", customer: "1234")
```
will produce the following log entry when using the `logfmt` formatter:
```
16:54:29.919 [info] service=payment-processor event=start-processing customer=1234
```
"""
@spec log(
level :: Logger.level(),
message :: Logger.message(),
metadata :: Logger.metadata()
) :: :ok
def log(level, fields_or_message_or_func, metadata \\ [])
def log(level, func, metadata) when is_function(func),
do: Logger.log(level, fn -> formatter().format(func.()) end, metadata)
def log(level, fields_or_message, metadata) do
Logger.log(
level,
fn -> formatter().format(fields_or_message) end,
metadata
)
end
@doc """
Logs details about the given `conn` at the given `level`.
See the module documentation for more information on configuration options.
Returns `:ok`.
"""
@spec log_conn(
level :: Logger.level(),
conn :: Plug.Conn.t(),
duration_us :: integer(),
metadata :: Logger.metadata()
) :: :ok
def log_conn(level, conn, duration_us, metadata \\ []) do
log(
level,
fn -> conn |> get_conn_fields(duration: format_duration(duration_us)) end,
metadata
)
end
defp formatter(formatter \\ Application.get_env(:logster, :formatter, :string))
defp formatter(:string), do: Logster.Formatters.String
defp formatter(:json), do: Logster.Formatters.JSON
defp formatter(other), do: other
@doc false
def log_level(_, %{private: %{logster_log_level: level}}), do: level
def log_level(nil, %{status: status}) when is_integer(status) and status >= 500, do: :error
def log_level(nil, %{status: status}) when is_integer(status) and status >= 400, do: :warning
def log_level(nil, _conn), do: :info
def log_level(level, _conn) when is_atom(level), do: level
def log_level({mod, fun, args}, conn) when is_atom(mod) and is_atom(fun) and is_list(args) do
apply(mod, fun, [conn | args])
end
@doc false
def handle_phoenix_event(
[:phoenix, :endpoint, :stop],
%{duration: duration},
%{conn: conn} = metadata,
_
) do
case log_level(metadata[:options][:log], conn) do
false -> :ok
level -> log_conn(level, conn, duration)
end
end
@doc false
def handle_phoenix_event([:phoenix, :socket_connected], _, %{log: false}, _), do: :ok
@doc false
def handle_phoenix_event(
[:phoenix, :socket_connected],
%{duration: duration},
%{log: level} = meta,
_
) do
log(level, fn ->
%{
transport: transport,
params: params,
user_socket: user_socket,
result: result,
serializer: serializer
} = meta
[
action: :connect,
state: result,
socket: inspect(user_socket),
duration: format_duration(duration),
transport: Atom.to_string(transport),
serializer: inspect(serializer)
]
|> append_params(params)
end)
end
@doc false
def handle_phoenix_event(
[:phoenix, :channel_joined],
%{duration: duration},
%{socket: socket} = metadata,
_
) do
channel_log(:log_join, socket, fn ->
%{result: result, params: params} = metadata
[
action: :join,
state: result,
topic: socket.topic,
duration: format_duration(duration)
]
|> append_params(params)
end)
end
@doc false
def handle_phoenix_event(
[:phoenix, :channel_handled_in],
%{duration: duration},
%{socket: socket} = metadata,
_
) do
channel_log(:log_handle_in, socket, fn ->
%{event: event, params: params} = metadata
[
action: :handled,
event: event,
topic: socket.topic,
channel: inspect(socket.channel),
duration: format_duration(duration)
]
|> append_params(params)
end)
end
defp channel_log(_log_option, %{topic: "phoenix" <> _}, _fun), do: :ok
defp channel_log(log_option, %{private: private}, fun) do
if level = Map.get(private, log_option) do
log(level, fun)
end
end
@spec get_conn_fields(Plug.Conn.t(), keyword) :: list
@doc false
def get_conn_fields(%Plug.Conn{} = conn, extra_fields \\ []) do
# We use `Keyword.put` to add items to the list, which prepends items to the list, and so we
# add items in reverse order of how we want them to appear in the log message.
extra_fields
|> maybe_put_headers(conn)
|> Keyword.put(:status, conn.status)
|> maybe_put_query_params(conn)
|> put_params(conn)
|> maybe_put_phoenix_info(conn)
|> Keyword.put(:path, conn.request_path)
|> Keyword.put(:method, conn.method)
|> maybe_put_host(conn)
|> Keyword.put(:state, format_state(conn.state))
|> maybe_remove_excluded_fields()
|> maybe_rename_fields()
end
defp format_state(:set_chunked), do: "chunked"
defp format_state(_), do: "sent"
defp maybe_put_host(fields, %Plug.Conn{host: host}) do
if extra_fields() |> Enum.member?(:host) do
fields |> Keyword.put(:host, host)
else
fields
end
end
defp maybe_put_phoenix_info(fields, %Plug.Conn{
private: %{phoenix_controller: controller, phoenix_action: action}
}) do
fields
|> Keyword.put(:action, Atom.to_string(action))
|> Keyword.put(:controller, inspect(controller))
end
defp maybe_put_phoenix_info(fields, _), do: fields
defp put_params(fields, %Plug.Conn{params: %Plug.Conn.Unfetched{}}),
do: fields |> Keyword.put(:params, "[UNFETCHED]")
defp put_params(fields, %Plug.Conn{params: params}), do: put_params(fields, params)
defp put_params(fields, params) do
params =
params
|> filter_values()
|> format_values()
fields |> Keyword.put(:params, params)
end
defp maybe_put_query_params(fields, conn) do
if extra_fields() |> Enum.member?(:query_params) do
fields |> do_put_query_params(conn)
else
fields
end
end
defp do_put_query_params(fields, %Plug.Conn{query_params: %Plug.Conn.Unfetched{}}),
do: fields |> Keyword.put(:query_params, "[UNFETCHED]")
defp do_put_query_params(fields, %Plug.Conn{query_params: query_params}),
do: do_put_query_params(fields, query_params)
defp do_put_query_params(fields, query_params) do
query_params =
query_params
|> filter_values()
|> format_values()
fields |> Keyword.put(:query_params, query_params)
end
# convenience method to put the params at the end of the given list
defp append_params(fields, params), do: fields ++ put_params([], params)
defp maybe_put_headers(fields, conn),
do: do_maybe_put_headers(fields, conn, Application.get_env(:logster, :headers, []))
defp do_maybe_put_headers(fields, _conn, []), do: fields
defp do_maybe_put_headers(fields, conn, loggable_headers) do
headers =
conn.req_headers
|> Enum.filter(fn {k, _} -> Enum.member?(loggable_headers, k) end)
|> Enum.into(%{}, fn {k, v} -> {k, v} end)
fields |> Keyword.put(:headers, headers)
end
defp maybe_remove_excluded_fields(fields),
do: fields |> Keyword.drop(Application.get_env(:logster, :excludes, []))
defp maybe_rename_fields(params, renames \\ Application.get_env(:logster, :renames, []))
defp maybe_rename_fields(fields, []), do: fields
defp maybe_rename_fields(fields, renames) do
renames_map = renames |> Enum.into(%{})
fields
|> Enum.map(fn {key, value} ->
if new_key = Map.get(renames_map, key) do
{new_key, value}
else
{key, value}
end
end)
end
defp filter_values(
params,
filter_config \\ Application.get_env(
:logster,
:filter_parameters,
@default_filter_parameters
)
)
defp filter_values(params, {:discard, discard_params}),
do: discard_values(params, discard_params)
defp filter_values(params, {:keep, keep_params}), do: keep_values(params, keep_params)
defp filter_values(params, filtered_params), do: discard_values(params, filtered_params)
defp discard_values(%{__struct__: mod} = struct, filter_config) when is_atom(mod) do
struct
|> Map.from_struct()
|> Enum.map(fn {k, v} -> {Atom.to_string(k), v} end)
|> Enum.into(%{})
|> discard_values(filter_config)
end
defp discard_values(%{} = map, discard_params) do
Enum.into(map, %{}, fn {k, v} ->
if is_binary(k) and String.contains?(k, discard_params) do
{k, "[FILTERED]"}
else
{k, discard_values(v, discard_params)}
end
end)
end
defp discard_values([_ | _] = list, discard_params),
do: Enum.map(list, &discard_values(&1, discard_params))
defp discard_values(other, _discard_params), do: other
defp keep_values(%{__struct__: mod}, _keep_params) when is_atom(mod), do: "[FILTERED]"
defp keep_values(%{} = map, keep_params) do
Enum.into(map, %{}, fn {k, v} ->
if is_binary(k) and k in keep_params do
{k, discard_values(v, [])}
else
{k, keep_values(v, keep_params)}
end
end)
end
defp keep_values([_ | _] = list, keep_params) do
Enum.map(list, &keep_values(&1, keep_params))
end
defp keep_values(_other, _keep_params), do: "[FILTERED]"
defp format_values(params), do: params |> Enum.into(%{}, &format_value/1)
defp format_value({key, value}) when is_binary(value) do
if String.valid?(value) do
{key, value}
else
{key, URI.encode(value)}
end
end
defp format_value(val), do: val
defp format_duration(duration) do
microseconds = duration |> System.convert_time_unit(:native, :microsecond)
microseconds / 1000
end
defp extra_fields, do: Application.get_env(:logster, :extra_fields, [])
end