defmodule Ink do
@moduledoc """
A backend for the Elixir `Logger` that logs JSON and filters your secrets.
## Usage
To use `Ink` for your logging, just configure it as a backend:
config :logger, backends: [Ink]
# optional additional configuration
config :logger, Ink,
name: "your app",
level: :info
### Options
In total, the following options are supported by `Ink`:
- `:name` the name of your app that will be added to all logs
- `:io_device` the IO device the logs are written to (default: `:stdio`)
- `:level` the minimum log level for outputting messages (default: `:debug`)
- `:status_mapping` the mapping to use for log statuses (default: `:bunyan`)
- `:filtered_strings` secret strings that should not be printed in logs
(default: `[]`)
- `:filtered_uri_credentials` URIs that contain credentials for filtering
(default: `[]`)
- `:metadata` the metadata keys that should be included in the logs (default:
all)
- `:exclude_hostname` exclude local `hostname` from the log (default:
false)
- `:log_encoding_error` whether to log errors that happen during JSON encoding
(default: true)
### Filtering secrets
`Ink` can be configured to filter secrets out of your logs:
config :logger, Ink,
filtered_strings: ["password"]
Sometimes, you configure a connection using a URL. For example, a RabbitMQ
connection could be configured with the URL
`"amqp://user:password@localhost:5672"`. Filtering the whole URL from your
logs doesn't do you any good. Therefore, `Ink` has a separate option to pass
secret URLs:
config :logger, Ink,
filtered_uri_credentials: ["amqp://user:password@localhost:5672"]
This code will parse the URL and only filter `"password"` from your logs.
#### Preventing reports on the terminal
When processes crash - which is a normal thing to happen in Elixir - OTP sends
reports to the handlers of the `:error_logger`. In some environments, there is
a default handler that prints these to the terminal. Since it includes the
state of the crashed process, this can include secrets from your application.
`Ink` is unable to filter these reports, because they are not printed using
the `Logger`.
You can disable printing of these reports with the following line in your
config:
config :sasl, sasl_error_logger: false
### Metadata
If you don't configure any specific metadata, `Ink` will include all metadata
as separate fields in the logged JSON. If you only want to include specific
metadata in your logs, you need to configure the included fields.
config :logger, Ink,
metadata: [:pid, :my_field]
*Note*: Since the term PID is also prevalent in the UNIX world, services like
LogStash expect an integer if they encounter a field named `pid`. Therefore,
`Ink` will log the PID as `erlang_pid`.
"""
@behaviour :gen_event
def init(__MODULE__) do
{:ok, configure(Application.get_env(:logger, Ink, []), default_options())}
end
def handle_call({:configure, options}, state) do
{:ok, :ok, configure(options, state)}
end
def handle_event({_, gl, {Logger, _, _, _}}, state) when node(gl) != node() do
{:ok, state}
end
def handle_event(:flush, state) do
{:ok, state}
end
def handle_event({level, _, {Logger, message, timestamp, metadata}}, state) do
log_message(message, level, timestamp, metadata, state)
{:ok, state}
end
def handle_info(_msg, state) do
{:ok, state}
end
def terminate(_reason, _state) do
:ok
end
def code_change(_old, state, _extra) do
{:ok, state}
end
defp configure(options, state) do
state
|> Map.merge(Enum.into(options, %{}))
|> update_secret_strings
end
defp log_message(message, level, timestamp, metadata, config) do
if Logger.compare_levels(level, config.level) != :lt do
message
|> base_map(timestamp, level, config)
|> Map.merge(process_metadata(metadata, config))
|> Ink.Encoder.encode()
|> log_json(config)
end
end
defp process_metadata(metadata, config) do
metadata
|> filter_metadata(config)
|> rename_metadata_fields
|> Enum.into(%{})
|> Map.delete(:time)
end
defp filter_metadata(metadata, %{metadata: nil}), do: metadata
defp filter_metadata(metadata, config) do
metadata |> Enum.filter(fn {key, _} -> key in config.metadata end)
end
defp rename_metadata_fields(metadata) do
metadata
|> Enum.map(fn
{:pid, value} -> {:erlang_pid, value}
other -> other
end)
end
defp log_json({:ok, json}, config) do
json
|> filter_secret_strings(config.secret_strings)
|> log_to_device(config.io_device)
end
defp log_json(other, config) do
case config.log_encoding_error do
true -> log_to_device(inspect(other), config.io_device)
_ -> :ok
end
end
defp log_to_device(msg, io_device), do: IO.puts(io_device, msg)
defp base_map(message, timestamp, level, %{exclude_hostname: true} = config)
when is_binary(message) do
%{
name: name(),
pid: System.pid() |> String.to_integer(),
msg: message,
time: formatted_timestamp(timestamp),
level: level(level, config.status_mapping),
v: 0
}
end
defp base_map(message, timestamp, level, config) when is_binary(message) do
%{
name: name(),
pid: System.pid() |> String.to_integer(),
hostname: hostname(),
msg: message,
time: formatted_timestamp(timestamp),
level: level(level, config.status_mapping),
v: 0
}
end
defp base_map(message, timestamp, level, config) when is_list(message) do
base_map(IO.iodata_to_binary(message), timestamp, level, config)
end
defp formatted_timestamp({date, {hours, minutes, seconds, milliseconds}}) do
{date, {hours, minutes, seconds}}
|> NaiveDateTime.from_erl!({milliseconds * 1000, 3})
|> DateTime.from_naive!("Etc/UTC")
|> DateTime.to_iso8601()
end
defp update_secret_strings(config) do
secret_strings =
config.filtered_strings
|> Kernel.++(uri_credentials(config.filtered_uri_credentials))
|> Enum.reject(fn s -> s == "" || is_nil(s) end)
Map.put(config, :secret_strings, secret_strings)
end
defp uri_credentials(uris) do
uris
|> Enum.reject(&is_nil/1)
|> Enum.map(fn uri -> uri |> URI.parse() |> Map.get(:userinfo) end)
|> Enum.reject(&is_nil/1)
|> Enum.map(fn userinfo -> userinfo |> String.split(":") |> List.last() end)
end
defp filter_secret_strings(message, secret_strings) do
Enum.reduce(secret_strings, message, fn secret, msg ->
String.replace(msg, secret, "[FILTERED]")
end)
end
defp default_options do
%{
level: :debug,
status_mapping: :bunyan,
filtered_strings: [],
filtered_uri_credentials: [],
secret_strings: [],
io_device: :stdio,
metadata: nil,
exclude_hostname: false,
log_encoding_error: true
}
end
# https://github.com/trentm/node-bunyan#levels
defp level(level, :bunyan) do
case level do
:debug -> 20
:info -> 30
:warn -> 40
:error -> 50
end
end
# http://erlang.org/documentation/doc-10.0/lib/kernel-6.0/doc/html/logger_chapter.html#log-level
defp level(level, :rfc5424) do
case level do
:debug -> 7
:info -> 6
:warn -> 4
:error -> 3
end
end
defp hostname do
with {:ok, hostname} <- :inet.gethostname(), do: List.to_string(hostname)
end
defp name do
:logger
|> Application.get_env(Ink)
|> Keyword.fetch!(:name)
end
end
