Logger backend with filters

config_eg.exs

config :logger, level: :debug,
    backends: [
      {Logger.Backends.FilterConsole, :debug_log},
      {Logger.Backends.FilterConsole, :error_log}
    ]
    
# log my_app at debug level
config :logger, :debug_log,
  level: :debug,
  format: "[$level] $message\n",
  metadata: [:application],
  metadata_filter: [application: :my_app]

# log everything else at :error level
config :logger, :error_log,
  level: :error,
  format: "[$level] $message\n",
  metadata: [:application],
  metadata_filter: [application: {:not, [:my_app]}]

filter_console_logger.ex

defmodule Logger.Backends.FilterConsole do
  @moduledoc """
  Filtering logger, allows debug level per application:

  ```
  use Mix.Config

  config :logger,
    backends: [
      {Logger.Backends.FilterConsole, :debug_log},
      {Logger.Backends.FilterConsole, :error_log}
    ]

  # log :my_app at :debug level
  config :logger, :debug_log,
    level: :debug,
    format: "DBG: $time [$level] $metadata $message\n",
    metadata: [:application],
    metadata_filter: [application: :my_app]

  # log everything else at :error level
  config :logger, :error_log,
    level: :error,
    format: "ERR: $time [$level] $metadata $message\n",
    metadata: [:application],
    metadata_filter: [application: {:not, [:my_app]}]
  ```

  See https://gist.github.com/benperiton/94a02edeef7684c4b3bd6422e4b10118
  """

  @behaviour :gen_event

  defstruct [format: nil, metadata: nil, level: nil, colors: nil, device: nil,
             max_buffer: nil, buffer_size: 0, buffer: [], ref: nil, output: nil,
             metadata_filter: nil]

  def init({__MODULE__, name}) do
    config = Application.get_env(:logger, name)
    device = Keyword.get(config, :device, :user)

    if Process.whereis(device) do
      {:ok, init(config, %__MODULE__{})}
    else
      {:error, :ignore}
    end
  end

  def handle_call({:configure, options}, state) do
    {:ok, :ok, init(options, state)}
  end

  def handle_event({_level, gl, _event}, state) when node(gl) != node() do
    {:ok, state}
  end

  def handle_event({level, _gl, {Logger, msg, ts, md}}, state) do
    %{level: log_level, ref: ref, buffer_size: buffer_size,
      max_buffer: max_buffer, metadata_filter: metadata_filter} = state
    cond do
      not metadata_matches?(md, metadata_filter) ->
        {:ok, state}
      not meet_level?(level, log_level) ->
        {:ok, state}
      is_nil(ref) ->
        {:ok, log_event(level, msg, ts, md, state)}
      buffer_size < max_buffer ->
        {:ok, buffer_event(level, msg, ts, md, state)}
      buffer_size === max_buffer ->
        state = buffer_event(level, msg, ts, md, state)
        {:ok, await_io(state)}
    end
  end

  def handle_event(:flush, state) do
    {:ok, flush(state)}
  end

  def handle_event(_, state) do
    {:ok, state}
  end

  def handle_info({:io_reply, ref, msg}, state = %{ref: ref}) do
    {:ok, handle_io_reply(msg, state)}
  end

  def handle_info({:DOWN, ref, _, pid, reason}, %{ref: ref}) do
    raise "device #{inspect pid} exited: " <> Exception.format_exit(reason)
  end

  def handle_info(_, state) do
    {:ok, state}
  end

  def code_change(_old_vsn, state, _extra) do
    {:ok, state}
  end

  def terminate(_reason, _state) do
    :ok
  end

  ## Helpers

  defp meet_level?(_lvl, nil), do: true

  defp meet_level?(lvl, min) do
    Logger.compare_levels(lvl, min) != :lt
  end

  def metadata_matches?(_md, nil), do: true
  def metadata_matches?(_md, []), do: true
  def metadata_matches?(md, [{key, {:not, exclusions}} | rest]) when is_list(exclusions) do
    case md[key] in exclusions do
      true ->
        false
      _ ->
        metadata_matches?(md, rest)
    end
  end
  def metadata_matches?(md, [{key, val} | rest]) do
    case Keyword.fetch(md, key) do
      {:ok, ^val} ->
        metadata_matches?(md, rest)
      _ -> false
    end
  end


  defp init(config, state) do
    level = Keyword.get(config, :level)
    device = Keyword.get(config, :device, :user)
    format = Logger.Formatter.compile Keyword.get(config, :format)
    colors = configure_colors(config)
    metadata = Keyword.get(config, :metadata, [])
    max_buffer = Keyword.get(config, :max_buffer, 32)
    metadata_filter = Keyword.get(config, :metadata_filter)

    %{state | format: format, metadata: Enum.reverse(metadata),
              level: level, colors: colors, device: device, max_buffer: max_buffer,
              metadata_filter: metadata_filter}
  end

  defp configure_colors(config) do
    colors = Keyword.get(config, :colors, [])
    %{debug: Keyword.get(colors, :debug, :cyan),
      info: Keyword.get(colors, :info, :normal),
      warn: Keyword.get(colors, :warn, :yellow),
      error: Keyword.get(colors, :error, :red),
      enabled: Keyword.get(colors, :enabled, IO.ANSI.enabled?)}
  end

  defp log_event(level, msg, ts, md, state = %{device: device}) do
    output = format_event(level, msg, ts, md, state)
    %{state | ref: async_io(device, output), output: output}
  end

  defp buffer_event(level, msg, ts, md, state) do
    %{buffer: buffer, buffer_size: buffer_size} = state
    buffer = [buffer | format_event(level, msg, ts, md, state)]
    %{state | buffer: buffer, buffer_size: buffer_size + 1}
  end

  defp async_io(name, output) when is_atom(name) do
    case Process.whereis(name) do
      device when is_pid(device) ->
        async_io(device, output)
      nil ->
        raise "no device registered with the name #{inspect name}"
    end
  end

  defp async_io(device, output) when is_pid(device) do
    ref = Process.monitor(device)
    send(device, {:io_request, self(), ref, {:put_chars, :unicode, output}})
    ref
  end

  defp await_io(state = %{ref: nil}), do: state

  defp await_io(state = %{ref: ref}) do
    receive do
      {:io_reply, ^ref, :ok} ->
        handle_io_reply(:ok, state)
      {:io_reply, ^ref, error} ->
        # credo:disable-for-lines:2
        handle_io_reply(error, state)
        |> await_io()
      {:DOWN, ^ref, _, pid, reason} ->
        raise "device #{inspect pid} exited: " <> Exception.format_exit(reason)
    end
  end

  defp format_event(level, msg, ts, md, state) do
    %{format: format, metadata: keys, colors: colors} = state
    format
    |> Logger.Formatter.format(level, msg, ts, take_metadata(md, keys))
    |> color_event(level, colors, md)
  end

  defp take_metadata(metadata, keys) do
    Enum.reduce keys, [], fn key, acc ->
      case Keyword.fetch(metadata, key) do
        {:ok, val} -> [{key, val} | acc]
        :error     -> acc
      end
    end
  end

  defp color_event(data, _level, %{enabled: false}, _md), do: data

  defp color_event(data, level, colors = %{enabled: true}, md) do
    color = md[:ansi_color] || Map.fetch!(colors, level)
    [IO.ANSI.format_fragment(color, true), data | IO.ANSI.reset]
  end

  defp log_buffer(state = %{buffer_size: 0, buffer: []}), do: state

  defp log_buffer(state) do
    %{device: device, buffer: buffer} = state
    %{state | ref: async_io(device, buffer), buffer: [], buffer_size: 0,
      output: buffer}
  end

  defp handle_io_reply(:ok, state = %{ref: ref}) do
    Process.demonitor(ref, [:flush])
    log_buffer(%{state | ref: nil, output: nil})
  end

  defp handle_io_reply({:error, error = {:put_chars, :unicode, _}}, state) do
    retry_log(error, state)
  end

  defp handle_io_reply({:error, :put_chars}, state = %{output: output}) do
    retry_log({:put_chars, :unicode, output}, state)
  end

  defp handle_io_reply({:error, error}, _) do
    raise "failure while logging console messages: " <> inspect(error)
  end

  defp retry_log(error, state = %{device: device, ref: ref, output: dirty}) do
    Process.demonitor(ref, [:flush])
    case :unicode.characters_to_binary(dirty) do
      {_, good, bad} ->
        clean = [good | Logger.Formatter.prune(bad)]
        %{state | ref: async_io(device, clean), output: clean}
      _ ->
        # A well behaved IO device should not error on good data
        raise "failure while logging consoles messages: " <> inspect(error)
    end
  end

  defp flush(state = %{ref: nil}), do: state

  defp flush(state) do
    state
    |> await_io()
    |> flush()
  end
end