JSON logging in Elixir using a Custom Formatter

Elixir logging is awesome and extensible. You can write your own backend or a Formatter and make endless combinations with unlimited possibilities. JSON logs are the norm nowadays and there are plenty of ways to get JSON logs in #elixir. Ink :muscle: is an awesome hex package to make that happen. Add it to your project and all your logs will become JSON. There were 2 shortcomings though for me

  1. It only writes to stdout, though that would work in most cases but when you have to write to file it hits a wall.
  2. Is not an Ink issue per se but a Plug "feature" where it logs 2 entries, first of the endpoint invoked and second of the repsonse and execution time.

The 2nd issue makes it difficult to have all the information to a request on a single object and also it repeats data such as request-id and process. Also it doesn't even adds the user-agent to the request. To do that you need to add it your self in the metadata.

Fret not there is a solution to the logging of plug request  :sunglasses: plug_json_logger FTW.


plug_json_logger solves the 2nd issue as it combines both Plug requests and even adds user agent to it and even solves the 2nd one as well almost, as it works as a formatter so it can be integrated with any backend and can be used with LoggerFileBackend for output to file.

Almost to good but there is a catch and it ain't that it uses Poison 😅 but that if log message is not from Plug it get printed out as plain text with no formatting , no JSON 😱. Once again fret not this is where Logger's custom formatter power comes to play.

You can define a formatter that can help you format your non JSON-ish messages before they output to your backend here is a quick and dirty formatter to make it happen I hacked after reading timber.io blog, link on the gist.

defmodule Formatter.Log do
  @moduledoc """
   This is a good resource to learn about formatters

  def format(level, message, timestamp, metadata) do
    |> Jason.decode()
    |> case do
      {:ok, msg} -> msg
      {:error, _} -> %{msg: message}
    |> json_msg_format(level, timestamp, metadata)
    |> new_line()

  def json_msg_format(message, level, timestamp, metadata) do
      timestamp: fmt_timestamp(timestamp),
      level: level,
      message: message,
      module: metadata[:module],
      function: metadata[:function],
      line: metadata[:line]
    |> Jason.encode()
    |> case do
      {:ok, msg} -> msg
      {:error, reason} -> %{error: reason} |> Jason.encode()

  def new_line(msg), do: "#{msg}\n"

  defp fmt_timestamp({date, {hh, mm, ss, ms}}) do
    with {:ok, timestamp} <- NaiveDateTime.from_erl({date, {hh, mm, ss}}, {ms * 1000, 3}),
         result <- NaiveDateTime.to_iso8601(timestamp) do

plug request log


non plug log

{"function":"ip/0","level":"info","line":17,"message":{"msg":"Ipify detected IP: X.X.X.X"},"module":"Elixir.Services.Ipify.Api","timestamp":"2021-09-13T11:27:49.324Z"}

and just make this all happen with adding config as below

 use Mix.Config
 config :plug_logger_json,
   filtered_keys: ["password", "authorization"],
   suppressed_keys: ["api_version", "log_type"]
 config :logger,
   backends: [{LoggerFileBackend, :info_log}],
   utc_log: true,
   handle_otp_reports: true
 # configuration for the {LoggerFileBackend, :info_log} backend
 config :logger, :info_log,
   format: {Formatter.Log, :format},
   metadata: :all,
   path: "/src/log/app.log",
   level: :info

Elixir Logger is just amazing and super flexible with tons of formatters and backends available and if you don't find something satisfying your needs just hack one out. Hope this gave you enough info to hack your solution

View Comments