Log through telemetry! 🤩
Notes
Do you ever have log statements right next to telemetry calls?
For example, imagine you have something a LiveView counter with “increase” and “decrease” events:
def handle_event("increase", _, socket) do
socket = update(socket, :count, fn count -> count + 1 end)
count = socket.assigns.count
:telemetry.execute([:scout, :counter, :increase], %{count: count})
Logger.info("Increasing count to #{inspect(count)}")
{:noreply, socket}
end
def handle_event("decrease", _, socket) do
socket = update(socket, :count, fn count -> count - 1 end)
count = socket.assigns.count
:telemetry.execute([:scout, :counter, :decrease], %{count: count})
Logger.info("decreasing count to #{inspect(count)}")
{:noreply, socket}
end
Every time we “increase” or “decrease” the counter, we’re creating a telemetry event (perhaps for our third-party analytics) and also logging that information.
Seems a little duplicative, right?
Consuming our own telemetry
What if we make our own app consume our telemetry events and create logs from them?
That way we can have a single place to log those events and we reduce the duplication!
We can do that by adding telemetry handlers when our application starts. In my
case, I’ll do that via a Scout.Logger.install/0 call:
# in application.ex
def start(_type, _args) do
Scout.Logger.install()
Now, if you look at that function, you’ll see it sets up a couple of handlers for our events. And in those handlers, we can do the logging we were doing before:
defmodule Scout.Logger do
require Logger
def install do
handlers = %{
[:scout, :counter, :increase] => &__MODULE__.handle_counter/4,
[:scout, :counter, :decrease] => &__MODULE__.handle_counter/4
}
for {key, fun} <- handlers do
:telemetry.attach({__MODULE__, key}, key, fun, :ok)
end
end
def handle_counter([:scout, :counter, :increase], %{count: count}, _, _) do
Logger.info("Increasing count to #{inspect(count)}")
end
def handle_counter([:scout, :counter, :decrease], %{count: count}, _, _) do
Logger.info("decreasing count to #{inspect(count)}")
end
end
That’s it! Now we can remove the duplicate Logger.info/1 calls from our
LiveView. 🥳
P.S. Want some more examples? Take a look at Phoenix.Logger