Elixir Logger and Erlang filters

Imagine you manage a fleet of Raspberry Pis deployed in shipping containers (the real ones, not the docker ones) that control all the environment variables of your hydroponic lettuce farm spread across the world.

Now imagine how noisy those Pi logs can be.

Let's say one of your Pis is not properly authorizing workers inside the container. Every time a worker types a password and verifies biometry the Pi should emit and log an event. But it also logs sensor data and timesheet of workers on that site.

Because of that, logging into the Pi and watching it spit out logs is not very human friendly. That's where Erlang :logger filters can come in handy.

Erlang released this new :logger in OTP 21 and Elixir released a put_module_level/2 in version 1.11.0.

Considering we're using the Logger macros to generate those, like Logger.info/2 or any other level we have as of today,

[:emergency, :alert, :critical, :error, :warning, :notice, :info, :debug]

We have the guarantee that some metadata is present, like which module generated the logs. We can also leverage that Elixir modules are atoms and use that to dynamically choose to silence some module logs.

So, what we'll do is create a module to filter the noisy modules:

defmodule HydroLettyce.LoggerHandler do
  @moduledoc """
  Let's filter some logs!
  """
  @noisy_modules [HydroLettyce.Sensors.Temperature, HydroLettyce.Auth.Biometry]
  
  # ... format or other functions you want to

  @spec filter(map(), keyword()) :: :stop | :ignore | map()
  def filter(%{meta: %{mfa: {module, _, _}}} = _log_event, _opts)
      when module in @noisy_modules do
    case Logger.get_module_level(HydroLettyce.NoisyLogs) do
      [{LogVideo, :none}] -> :stop
      _ -> :ignore
    end
  end
end

and we should also tell our Application.start/2 that our logger has a new global filter:

# HydroLettyce.Application module, application.ex file
@impl true
@spec start(atom(), keyword()) :: {:ok, pid()} | {:error, any()}
def start(_type, _args) do
  # ...
  :logger.add_primary_filter(:noise_filter, {&HydroLettyce.LoggerHandler.filter/2, []})
  # ...
end

That said, we can just iex (or an RPC call) and:

iex> Logger.put_module_level(HydroLettyce.NoisyLogs, :none)
:ok

What just happened here?

When calling Logger.put_module_level(HydroLettyce.NoisyLogs, :none) we ask logger to add to its own ETS table that the atom :'Elixir.HydroLettyce.NoisyLogs' has :none level set.

Then, as the application has already started with the HydroLettyce.LoggerHandler.filter/2 and we have a Logger.get_module_level(HydroLettyce.NoisyLogs) call, we'll get the :none level and :stop the logging flow to not pass the log forward. Everything else will be :ignored by our filter and forwarded to other logs. The add_primary_filter/2 function doesn't replace the default log filter but adds our custom to a list of global filters.

One important (and usually useful) tip here is that the log filters execute in the same process as the log caller and because of that, have no backpressure strategy. Also, consider the filter function performance (try not making network calls) because that would easily become a bottleneck for your application overall.

For reference and more information for deep dives, see:

#elixir #otp