ink.ex

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