Elixir Learnings: Structured Logging

When logging from the backend, it is useful to have the logs structured so that they may be sent to an external logging service or saved in log files and then be parsed by the service or a script to create reports or gather some type of data.

In this recipe, I am going to demonstrate setting up logging with a JSON structure.

A working example can be found at Github Elixir Logging

Ingredients

• 1 elixir application
• 1 logger_json hex package
• 1 jason hex package
• 10 ounces of direction following
• a pinch of copy/paste

Directions

Configurations

Let’s start in the mix.exs file.

Add {:logger_json, "~> 5.0"} to the deps block. As of this writing, the current version is 5.0. Adjust the version to taste.

Also, ensure that {:jason, "~> 1.3"} is also in the deps block as we will be using this as the JSON generator/parser. Again, you may adjust the version to taste.

If you would like to use a different library for JSON, that is fine, but this recipe will refer to jason.

Now to the configs.

The app always executes the config/config.exs (root config) first. At the bottom of that file, the config for the current environment is included dynamically. The config for the current environment may have values that override values in the root config. Because of this, we can put common values in the root config and expect them to be overridden as needed.

In the config/config.exs add the following towards the top of the file:

env = config_env()
is_prod = env == :prod
is_dev = env == :dev
is_test = env == :test

The current environment is being captured in a variable called env. Helper variables are then created that hold a boolean to indicate if the current environment is dev, prod, test, etc.

Just under the above adde code add:

log_level =
cond do
  is_dev -> :debug
  is_prod -> :info
  is_test -> :warn
end

This creates a variable that holds the log level based on the current environment.

Once again, just under the above added code, add:

# Load the environment variables from the appropriate .env file.
env_ext = if is_prod, do: "", else: "-#{env}"

try do
# In case .env file does not exist.
File.stream!("./.env#{env_ext}")
# Remove excess whitespace
|> Stream.map(&String.trim_trailing/1)
# Loop through each line
|> Enum.each(fn line ->
  line
  # Split on *first* "=" (equals sign)
  |> String.split("=", parts: 2)
  # stackoverflow.com/q/33055834/1148249
  |> Enum.reduce(fn value, key ->
    # Skip all comments
    if key |> String.starts_with?("#") == false do
      # Set each environment variable
      System.put_env(key, value)
    end
  end)
end)
rescue
_ ->
  IO.puts(
    IO.ANSI.yellow() <>
      "There was no `.env#{env_ext}` file found. Please ensure the required environment variables have been set." <>
      IO.ANSI.reset()
  )
end

This will read the environment variable set in the .env files.

Next, still in the root config (config/config.exs), add a configuration key called json_logging like this:

config :elixir_logging, json_logging: true

This will allow the app to determine if structured JSON logging is enabled or not. By default it is.

Now configure the common logging values:

config :logger_json, :backend, on_init: {ElixirLogging.Logs.Logger, :load_config, [level: log_level]

}

# Configures Elixir's Logger
config :logger, backends: [LoggerJSON], level: log_level

The first config sets up json_logging to use the custom Logger module (which will be defined later in the recipe), tells it which function to call in the module, and passes the log level to the function.

The second line configures logger to use LoggerJSON as the logging app and sets the log level (per the variables set above).

See the complete file here.

Now create the config overrides for the various environments. Start with dev.

In the config/dev.exs add the following towards the top:

website_host = System.get_env("WEBSITE_HOST") || "localhost"

json_logging = !(website_host == "localhost" and System.get_env("CONSOLE_LOGGING"))

config :elixir_logging, json_logging: json_logging

The website_host variable is “localhost’ by default, but may be changed with an environment variable if needed.

The json_logging variable is a boolean. It will be false if the website host is “localhost” AND the CONSOLE_LOGGING environment variable is set.

The last config line overrides the json_logging configuration key from the default.

Again, in the dev config (config/dev.exs) add the following:

if not json_logging do
  config :logger, backends: [:console]
  # Do not include metadata nor timestamps in development logs
  config :logger, :console, format: "[$level] $message\n"
end

This will set “regular” console logging up if json_logging is disabled.

Duplicate what you just put in the dev config in the test config (config/test.exs). This will allow you to disable the JSON logs when running tests which is sometimes useful when debugging.

See an example of the complete dev config here and the complete test config here.

No need to edit the prod config (config/prod.exs) as it should use the defaults only.

Configuring for a release is similar but outside of the scope of this article as there are many ways to deploy and release an Elixir app. The information from the above configs should be enough to get you down the road.

See an example of a release config here.

Environment Variables

Copy the included .env-sample file to create a new .env-dev file and a new .env-test file.

In the .env-test file you can remove SECRET_KEY_BASE as it should be set as default in the test config.

These will get picked up in the configs per the code added above. They give us a simple way to disable or enable the structured logging locally.

Logging Modules

Create a new file called formatter.ex under lib/{app_name}/logging.

Populate the file with the following:

defmodule ElixirLogging.Logs.Formatter do
  @moduledoc """
  JSON log formatter.
  See: https://github.com/Nebo15/logger_json/blob/master/lib/logger_json/formatters/basic_logger.ex
  """

  import Jason.Helpers, only: [json_map: 1]

  alias LoggerJSON.{FormatterUtils, JasonSafeFormatter}

  @behaviour LoggerJSON.Formatter

  @processed_metadata_keys ~w[pid file line function module application]a

  @impl true
  def format_event(level, msg, ts, md, md_keys) do
  json_map(
    severity: Atom.to_string(level),
    time: FormatterUtils.format_timestamp(ts),
    message: IO.chardata_to_string(msg),
    metadata: format_metadata(md, md_keys)
  )
  end

  defp format_metadata(md, md_keys) do
    md
    |> LoggerJSON.take_metadata(md_keys, @processed_metadata_keys)
    |> FormatterUtils.maybe_put(:error, FormatterUtils.format_process_crash(md))
    |> JasonSafeFormatter.format()
  end
end

This is the “basic” formatter. Depending on the need, different formatting may be applied. See some other examples here.

Create a new file called logger.ex under lib/{app_name}/logging.

Populate it with the following:

defmodule ElixirLogging.Logs.Logger do
  @moduledoc """
  Includes functions for dynamically configuring logging.
  See: https://hexdocs.pm/logger_json/LoggerJSON.html#module-dynamic-configuration
  """

  alias ElixirLogging.Logs.Formatter

  @default [formatter: Formatter, json_encoder: Jason, level: :debug, metadata: :all]

  def load_config(_, {:level, level}) do
    config = @default |> merge_keyword_lists(:level, level)
    {:ok, config}
  end

  def load_config(_, _) do
    {:ok, @default}
  end

  defp merge_keyword_lists(primary, key, value) do
    try do
      Keyword.replace!(primary, key, value)
    rescue
      _ -> [{key, value} | primary]
    end
  end
end

This is the Module that was passed to the configuration with the load_config function. This leverages the formatter Module that we just created.

Ecto Logging

In lib/{app_name}/application.ex, add the following at the top of the start function:

if Application.fetch_env!(:elixir_logging, :json_logging) do
  :ok =
    :telemetry.attach(
      "logger-json-ecto",
      [:elixir_logging, :repo, :query],
      &LoggerJSON.Ecto.telemetry_logging_handler/4,
      :debug
    )
end

This checks if json logging is enabled. If so, it logs Ecto at debug level.

See an example of the application.ex file here.

Requests

To log requests made to the server add the following to lib/{app_name}_web/endpoint.ex:

if Application.fetch_env!(:elixir_logging, :json_logging) do
  plug LoggerJSON.Plug, formatter: LoggerJSON.Plug.MetadataFormatters.ELK
end

Again, this checks if json logging is enabled. If so, it uses the LoggerJSON plug to format requests. Here, the ELK formatter is being used, but you can adjust the formatter to taste.

See an example of the endpoint.ex file here.

More on the LoggerJSON plug and available formatters can be found here.

At this point, you should have structured logging throughout the app.

Conclusion

To create structured logging throughout the Elixir app was not too difficult. Enhancing it with the ability to turn it on or off while developing or testing seems like a “nice to have”. It created a small bit of complexity that I believe is worth it.

Enjoy the newly structured logs!