DEV Community: Ayman Osman

AWS SSM Parameters for Elixir secrets

Ayman Osman — Fri, 29 Apr 2022 11:17:33 +0000

This is a very short article about using AWS Systems Manager Parameter Store to load secret configuration in a simple way. One of the motivations for the approach I'm about to describe is the desire to avoid what I consider to be an anti-pattern. If you are not interested in that discussion, then feel free to skip to the code.

The Anti-Pattern

Elixir 1.9 introduced "releases", and with it an overhaul of how configuration is done. Before this, all configuration was resolved at build time, something that was not a problem for those who ran their apps "from source", as "build time" and "run time" were effectively the same. But for those who wanted to ship a pre-built app, this caused problems.

config :my_app,
  # when is this resolved?
  database_url: System.get_env("DATABASE_URL")

People solved this problem by adopting a pattern: set the variable to a placeholder value and defer the lookup till later.

config :my_app,
  normal_var: "I am totally normal",
  deferred_var: {:system, "SEE_YOU_LATER"}

In order for this to work, the consuming code would have to recognise this pattern.

def consume_config() do
  case Application.get_env(:my_app, :deferred_var) do
    {:system, var} -> System.get_env(var)
    value -> value
  end
end

The problem with this "anti-pattern" is it confused newcomers who wrongly assumed it was a feature of the configuration system itself, rather than what it actually was: an ad-hoc workaround, that had to be implemented for every library and variable one chose to support.

Happily, this is not a problem anymore, and the story around runtime configuration is much better: just put it all in config/runtime.exs.

Recently, I wanted to use AWS SSM to store secret configuration, and it looked like the way to go was to use Config.Provider. Looking around to see how others had solved the same problem, a familiar pattern cropped up.

config :my_app,
  some_var: {:ssm, "THIS_LOOKS_FAMILIAR"}

Because Config.Provider s run after config/runtime.exs is loaded, you needed some placeholder value that could later be detected and replaced.

This, I thought, was an instance of the same anti-pattern.

Deciding I didn't want to re-introduce the anti-pattern, I came up with a different approach.

A different approach

First, add the required dependencies and declare a Config.Provider.

defmodule Example.MixProject do
  def project do
    [
      ...
      releases: releases()
    ]
  end

  defp releases() do
    [
      example: [
        config_providers: [
          {Example.ConfigProvider, []}
        ]
      ]
    ]
  end

  defp deps do
    [
      ...
      {:ex_aws, "2.0"},
      {:ex_aws_ssm, "2.0"}
    ]
  end
end

And then, implement it as follows.

defmodule Example.ConfigProvider do
  @behaviour Config.Provider

  @impl true
  def init([]) do
    []
  end

  @impl true
  def load(config, _state) do
    {:ok, _} = Application.ensure_all_started(:hackney)
    {:ok, _} = Application.ensure_all_started(:ex_aws)

    params = get_parameters(config[:ex_aws]) |> Enum.into(%{})

    Config.Reader.merge(config,
      example: [
        {ExampleWeb.Endpoint, secret_key_base: params["secret_key_base"]},
        {Example.Repo, url: params["database_url"]}
      ]
    )
  end

  defp get_parameters(config) do
    ExAws.SSM.get_parameters_by_path(prefix(), with_decryption: true)
    |> ExAws.request(config)
    |> case do
         {:ok, %{"Parameters" => params}} ->
           params
           |> Enum.map(fn param ->
             {String.trim_leading(param["Name"], prefix()), param["Value"]}
           end)

         error ->
           raise "Failed to fetch parameters: #{inspect(error)}"
       end
  end

  defp prefix() do
    "/example/prod/"
  end
end

Essentially, instead of using a generic Config.Provider that relies on placeholder values to do its job, I wrote a one-off Config.Provider that added the configuration I wanted.

Regaining what was lost

This worked fine for me in the project I was working on, but looking back at it, I think it suffers from two problems.

There was something nice about the "wrong" approach: it was declarative and the configuration was all in one place.

I thought about an alternative that would help the code regain the clarity that was lost and this is what I came up with.

First, I started with what I thought was the simplest possible API.

config :my_app,
  some_var: System.get_env("SOME_VAR"),
  database_url: Secret.get_env("DATABASE_URL")

Just replace System.get_env(...) with Secret.get_env(...).

And got the following (admittedly rough) code working.

defmodule Secret do
  def get_env(key, default \\ nil) do
    Map.get(get_all_env(), key, default)
  end

  defp get_all_env() do
    case :ets.whereis(__MODULE__) do
      :undefined ->
        :ets.new(__MODULE__, [:set, :public, :named_table])

        {:ok, _} = Application.ensure_all_started(:hackney)
        {:ok, _} = Application.ensure_all_started(:ex_aws)

        env = fetch_env()
        :ets.insert(__MODULE__, {:env, env})
        env

      ref ->
        [{:env, env}] = :ets.lookup(ref, :env)
        env
    end
  end

  defp fetch_env() do
    config = [
      region: System.fetch_env!("AWS_REGION"),
      access_key_id: System.fetch_env!("AWS_ACCESS_KEY_ID"),
      secret_access_key: System.fetch_env!("AWS_SECRET_ACCESS_KEY")
    ]

    get_parameters(config) |> Enum.into(%{})
  end

  defp get_parameters(config) do
    # same as above
  end
end

$ aws ssm put-parameter \
  --name "/example/prod/DATABASE_URL" \
  --value "ecto://postgres:postgres@localhost/example_prod" \
  --type SecureString \
  --overwrite

> Secret.get_env("DATABASE_URL")

"ecto://postgres:postgres@localhost/example_prod"

I have yet to switch to this approach, but it is something I will consider next time I need to accomplish the same task.

Structured (JSON) logs in Elixir

Ayman Osman — Sun, 17 Apr 2022 11:31:57 +0000

The desire to produce structured logs is common. In this article, I will survey the major approaches one could take to achieve this goal using the built-in Elixir Logger.

As an example, I will use JSON as the "structured" format, as it seems to be the most common. The same points apply to any structured format you choose.

First, a quick recap of the important pieces of the Elixir Logger.

Log events are produced via the API functions such as Logger.info and Logger.warn. A log event is a "message", which is usually a string, paired with "metadata", which is a list of key-value pairs.

> Logger.info("200 OK", request_id: 42)

Log events are consumed by "backends".

import Config

config :logger,
  backends: [:console, OtherBackend]

Each backend is independent, making its own decisions about which log events to filter out and how to format them.

Finally, there is the configuration for each backend, with format and metadata being the only relevant ones for this article.

import Config

config :logger, :console,
  format: # describes the output format
  level: # sets the minimum log level to output
  metadata: # what metadata keys (if any) will be included in the output

Let's quickly see what kind of behaviour we get out-of-the-box.

With the following configuration:

import Config

config :logger, :console,
  metadata: [:request_id]

this is the kind of output you can expect to see:

> Logger.info("200 OK", request_id: 42)

12:00 request_id=42 [info] 200 OK

The output is determined by the format configuration parameter, which defaults to $time $metadata[$level] $message.

You may be wondering what happens if we provide a map instead of a string for the message argument. Here is what it looks like:

> Logger.info(%{status: 200, request_id: 42})

12:00 [info]  [request_id: 42, status: 200]

I'll explain what is going on here at the end of the article, but, for now, I will ignore this because it won't turn out to be usable.

Now let's look at the different approaches to structured logging.

Serializing into `$message` (the non-approach)

One approach that may occur to you is to forget about how the logging framework works and serialize messages into JSON yourself, like so:

> Logger.info(encode(%{status: 200, request_id: 42}))

12:00 [info] {"status": 200,"request_id":42}

Almost there, now you just need to get rid of the extra stuff in the way of your JSON formatted log.

import Config

config :logger, :console
  format: "$message\n"

> Logger.info(encode(%{status: 200, request_id: 42}))

{"status": 200,"request_id":42}

There we go. We now have JSON logs. But we lost the timestamp and log level. So we add them back.

> Logger.info(encode(%{timestamp: "12:00", level: :info, status: 200, request_id: 42}))

{"timestamp": "12:00","level": "info","status": 200,"request_id":42}

And it seems we have accomplished our task.

Obviously, I think this is a bad approach. Here are some of the reasons why:

You have to remember to include "level" and "timestamp" fields every time you produce a log event.

Something the logger is designed to do for you. If you think that you can solve that problem by wrapping the Elixir logger, then you should know that that is also a bad idea.

But most importantly,

it does not play well with third-party libraries.

Any other library that produces log events in a sane way,
i.e. by calling Logger.info("some message", ... metadata ...) will not participate in this scheme. So you will end up with a mixture of JSON formatted logs produced by your application and raw strings produced by other applications.

{"level":"info","timestamp":"12:00","message":"did something"}
Raw log from third-party library
{"level":"info","timestamp":"12:01","message":"did something else"}

Custom formatter - the most straightforward approach

In Elixir's logging framework there is a somewhat informal notion of a "custom formatter", this is a configuration parameter that lets the user of a logging backend customize the way log events are serialized. By convention, this piece of configuration is specified by the format key.

The simplest form of this parameter is a string.

import Config

config :logger, :console,
  format: "[$level] $message"

Which lets you specify simple formats, but this parameter can also be a {module, function} tuple which lets you take complete control over formatting.

import Config

config :logger, :console
  format: {MyApp.Logger.Formatter, :format}

Once you do that, it is just a matter of implementing this module and function.

defmodule MyApp.Logger.Formatter do
  def format(level, message, timestamp, metadata) do
    # encode the log event
  end
end

Now we have complete control. We also have to provide the metadata keys we wish to receive, as usual.

import Config

config :logger, :console
  format: {MyApp.Logger.Formatter, :format},
  metadata: [:request_id]

defmodule MyApp.Logger.Formatter do
  def format(level, message, timestamp, metadata) do
    log_event =
      to_json(
        %{
          timestamp: format_timestamp(timestamp),
          level: level,
          message: :erlang.iolist_to_binary(message)
        },
        metadata
      )

    encode(log_event)
  rescue
    _ -> "could not format: #{inspect({level, message, metadata})}"
  end

  defp to_json(...) # not every Erlang term is valid json, convert here
  defp format_timestamp(...)
end

We get the output we expect.

> Logger.info("nice stuff", request_id: 42)

{"timestamp":"12:00","level":"info","message":"nice stuff","request_id":42}

And with this, all third-party log events will also be formatted properly.

This approach will work for any backend which follows the convention of exposing a format configuration parameter.

A new backend - is overkill

The third and final approach that we will consider is creating a new backend. As I will show, it is no better than the previous approach. First, let's see a simplified implementation of a backend based on the built-in :console backend.

We tell the :logger application to send logs to our new backend.

import Config

config :logger,
  backends: [MyApp.Logger.Backends.Console]

And implement it as follows:

defmodule MyApp.Logger.Backends.Console do
  @behaviour :gen_event

  def init(_) do
    level = :info
    format = Logger.Formatter.compile("$time $metadata[$level] $message\n")
    metadata = [:request_id]
    device = Process.whereis(:user)

    {:ok, %{level: level, format: format, metadata: metadata, device: device}}
  end

  def handle_event({level, _group_leader, {Logger, message, timestamp, metadata}}, state) do
    %{level: min_level, format: format, metadata: keys, device: device} = state

    cond do
      # Filter out logs that are lower than the configured level
      Logger.compare_levels(level, min_level) == :lt ->
        {:ok, state}

      true ->
        :ok =
          :io.put_chars(
            device,
            Logger.Formatter.format(
              format,
              level,
              message,
              timestamp,
              Keyword.take(metadata, keys)
            )
          )

        {:ok, state}
    end
  end
end

Let's go over that in detail.

A backend is a gen_event, so we declare that we implement that behaviour.

We implement the callback init/1, which returns {:ok, state}, just like a GenServer. Normally, we would fetch configuration for the backend here and do any setup work which is required for that particular backend. For example, a file based backend may open a file and store the file handle. In this example, I locate the :user process and store its pid. The :user process is a special device which is responsible for output to the standard I/O streams, i.e. the console. I also "compile" the format template for later use.

Finally, we implement the handle_event/2 callback, which is the heart of the backend. It receives a log event, drops it if it is lower than the configured minimum log level, otherwise, it formats and sends it to the output device. You can see that this particular backend delegates formatting completely to another module: Logger.Formatter.

The Logger.Formatter module, given a format string, works in the following way:

> fmt = Logger.Formatter.compile("[$level] $message\n")
["[", :level, "] ", :message, "\n"]

> output = Logger.Formatter.format(fmt, :info, "200 OK", :no_timestamp, :no_metadata)
["[", "info", "] ", "200 OK", "\n"]

> :io.put_chars(:user, output)
[info] 200 OK
:ok

but when given a {module, function} tuple, it will simply delegate to that module.

> Logger.Formatter.compile({MyMod, :my_fun})
{MyMod, :my_fun}

> Logger.Formatter.format({MyMod, :my_fun}, level, message, timestamp, metadata)
# Just calls MyMod.my_fun(level, message, timestamp, metadata)

Seeing what a backend consists of you should be able to see that formatting happens entirely in Logger.Formatter.format/5. Which gets us back to where we were in the second approach.

Which is why I conclude:

Creating a new backend just to format log events is overkill.

Because, as the above code shows, it is no more flexible than a formatting module.

So when should you create a new backend? I'll tentatively propose a rule and my reasoning for it.

A logger backend is tasked with receiving log events and sending them to an output device. Only the backend is responsible for sending output to the device, therefore this suggests it has the following responsibilities:

managing the I/O device
and efficient use of the I/O device (i.e. buffering output)

In particular, the backend is not responsible for formatting output, that is left up to the Logger.Formatter module (or a custom formatter).

Which leads to the following rule:

Only create a new logger backend when you need to manage a new type of I/O device.

Each device may have particular needs in terms of setup and efficient use, and that can be encapsulated by the backend.

Examples of I/O devices that may warrant their own backends:

the standard I/O streams, i.e. the console
a file
a set of files with log rotation
a socket (for remote logging)

That's all I have to say about the different approaches to structured logging using the built-in Elixir logger.

Now I'd like to look at a potential future approach.

Reports - a future approach?

Earlier in the article we saw that the message argument to the Logger API functions need not be a string.

> Logger.info(%{status: 200, request_id: 42})

12:00 [info]  [request_id: 42, status: 200]

This may look promising until you realise that you have no control over how this message is formatted.[^1]

defmodule CustomFormatter do
  def format(level, message, timestamp, metadata) do
   # "message" is already formated into "[request_id: 42, status: 200]"
  end
end

So what is going on?

To understand this we need to look at how Elixir's logger is implemented on top of the Erlang logger.

The Erlang logger has its own design which differs in significant ways from the Elixir logger. To keep this article short, I will not explain the Erlang logger in detail, but poke around its API enough to give you an idea of the pieces.

The Erlang logger is organised into "handlers". When Elixir starts up, it registers the Logger module as a handler (replacing the default Erlang handler).

> :logger.get_handler_ids
[Logger]

You can take a look at the configuration:

> :logger.get_handler_config Logger
{:ok,
 %{
   ... elided ...,
   id: Logger,
   module: Logger.Handler
 }}

A "handler" configures a callback module to implement its behaviour, which is the Logger.Handler module, in this case. The callback that handles a log event is log/2 and what it receives is a little different to what a "backend" receives.

An Erlang "log event" has the following type:

@type log_event :: %{level: level(),
                     msg: {:report, map()}
                        | {:string, :unicode.chardata()},
                     meta: metadata()}

For example, a log event could be:

%{level: :info,
  msg: {:string, "200 OK"},
  meta: %{request_id: 42}}

%{level: :info,
  msg: {:report, %{status: 200, request_id: 42}},
  meta: %{}}

The name Erlang gives a structured log message is a "report". A report is just a map. The line of code responsible for formatting this report is here.

It turns into the following call:

> Kernel.inspect(Map.to_list(%{status: 200, request_id: 42}))
"[request_id: 42, status: 200]"

The Elixir logger's handler implementation will always render a report to a string before passing it to a backend. It is this fact that makes reports unusable for structured logging today.

I assume this was done for backwards-compatibility, after all, the Elixir Logger predates the Erlang logger.

One could imagine a change to the Elixir logger to allow backends to receive Erlang-style log events and bring the two systems closer together.

[^1] There is the report_cb callback, but it does not help.

Don't wrap the Elixir logger (or be careful if you do)

Ayman Osman — Tue, 12 Apr 2022 23:58:42 +0000

Elixir comes with a powerful and convenient logging facility exposed by the Logger module. It is used universally in Elixir projects, which makes the subject of logging far more approachable in Elixir than in most other languages, where the logging story is far less straightforward.

Basic usage of Logger may be enough for you, most of the time, but, sometimes, the need to customise some aspects of it will arise.

One way of achieving this is to wrap the lower level logging module. This is a completely natural thing to do. As a project grows, we will often wrap lower level functionality in order to enforce conventions and abstract repetitive code.

So you would think that it would be completely reasonable to wrap Elixir's Logger module, if the need to customise logging were to arise.

Here is the problem: you start to implement this solution by creating the following wrapper module:

defmodule MyLogger do
  require Logger
  def info(message, metadata \\ []) do
    Logger.info("[myprefix] " <> message, metadata)
  end
end

At first, everything seems to be working fine. You call this new wrapper function from another module and confirm that it is working as expected

defmodule Example do
  def work() do
    MyLogger.info("working...")
  end
end

iex(2)> Example.work

11:38:16.428 [info]  [myprefix] working ...

The problem is discovered when you decide to include source location information alongside the ordinary log message.

import Config

config :logger, :console,
  metadata: [:file, :function, :module]

iex(1)> Example.work

14:00:03.912 file=lib/my_logger.ex function=info/2 module=MyLogger [info]  [myprefix] working ...

As you can see, every log line reports the source of the log event as our new wrapping code. This is not what you wanted.

What is the problem?

The problem is the Logging API functions, such as Logger.info and Logger.debug, are not functions but macros, and, in this context, it matters where you call them.

Macros know in what files they are called, they have access to that information through the __CALLER__ special form. In fact, that is exactly how Logger captures this information.

By placing the Logger.info call in one place (and calling it in a function), you have inadvertently signalled to the logging system that all log events originate from that one location.

What is the solution?

Don't wrap the logging macros at all. You can probably achieve what you want by some other means. Look at the documentation for Custom Formatting to customise how a log event is serialised into a log line. If the Elixir logger is not flexible enough for you, consider looking at the lower level Erlang Logger for options.

I really want to wrap logging calls

If you insist on wrapping calls to the Elixir logger, then wrap it in a macro.

defmodule MyLogger do
  # I don't recommend doing this
  defmacro info(message, metadata \\ []) do
    quote do
      require Logger
      Logger.info("[myprefix] " <> unquote(message), unquote(metadata))
    end
  end
end

iex(1)> Example.work

13:09:48.324 file=lib/example.ex function=work/0 module=Example [info]  [myprefix] working ...

The reason this works is that the call to the macro Logger.info/2 now expands in the context of the call to MyLogger.info/2, and so, source location information is preserved.

As a demonstration of the kind of information that is available to a macro as it expands, here is an alternative macro

defmodule MyLogger do
  defmacro info(message, metadata \\ []) do
    env = __CALLER__

    quote bind_quoted: [
            message: message,
            metadata: metadata,
            file: env.file,
            line: env.line
          ] do
      require Logger

      Logger.info("source=#{Path.basename(file)}:#{line} #{message}", metadata)
    end
  end
end

iex(3)> Example.work

13:20:14.575 [info]  source=example.ex:5 working ...