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 :ignore
d 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:
- Fred Hebert on the new Erlang logger
- Elixir Logger docs
- Erlang logger docs