heroku/plexy

A toolkit for building excellent APIs with Elixir

Plexy

Interagent-compatible web services in Elixir, inspired by Pliny.

Plexy helps developers write and maintain excellent APIs. It integrates well with other services by implementing logs-as-data, request/response instrumentation, request IDs, and encourages good defaults for logging and exception reporting.

Notably, Plexy is not a framework or a set of code generators. You can use Plexy's plugs with an existing Phoenix or even a vanilla Elixir web app. Plexy will work with you, not dictate how you work. It is also database agnostic.

Installation

Add :plexy to your list of dependencies in mix.exs:

def deps do
  [
    {:plexy, "~> 0.3.0"}
  ]
end

Require Plexy plugs in your application:

defmodule MyRouter do
  use Plug.Router

  plug Plexy.RequestId
  plug Plexy.Instrumentor
  plug :match
  plug :dispatch
end

Call the Plexy.Logger wherever you wish to log information:

Plexy.Logger.count(:http_clients_404, 1)

Usage

Import the plugs into your Plug router or your Phoenix router pipeline as necessary. You can also import the plugs into your own plugs, as needed.

Concepts

Logs-as-data

By publishing consistent and machine-interpretable logs, we are able to monitor our applications and trace requests with tools like Librato and splunk.

It is useful to think of logs as data, instead of just as strings. For logs-as-data, we want to publish logs like

flag1 key1=val1 key2=val2 flag2

This is known as an l2met compatible log format. Outputting logs in this format will allow integrations like Librato to easily show graphs of this data, and allows us to search Splunk for matching loglines.

To output arbitrary data to the log, you can pass a hash to Plexy.Logger and it will format it correctly. For example:

Plexy.Logger.info(test: true, foo: "bar")

becomes

21:02:24.882 request_id=fc06cbd2-b8b6-4257-801d-89253ed83962  test=true foo=bar

You can pass in maps, structs and keyword lists to Plexy.Logger methods, and it will log them correctly without asking you to worry about converting them to strings.

Request IDs

Request IDs are a unique identifier associated with every single request your Plexy app receives. Importing the Plexy.RequestId plug will append the request ID to the connection and also make it available in the Logger metadata.

Request IDs are read on the request coming in to the app, so if you are on a platform like Heroku that adds Request ID headers, Plexy can read the existing Request ID(s) and append its own Request ID to the list. By default, it reads out of the list of headers ["Request-Id", "X-Request-Id"] for incoming requests, but you can configure this list by setting req_headers in Config.

Similarly, it defaults to setting a Request-Id header on the response so that you can easily trace requests. To customize this header, set res_header in Config.

Request/response instrumentation

By default, Plexy will instrument each request and output the timing information in loglines. This, in addition with a request ID, makes it possible to splunk for a particular request and see information about its performance, HTTP response code, etc. An example request / response might look like this in logs:

21:02:24.882 request_id=fc06cbd2-b8b6-4257-801d-89253ed83962  at=start instrumentation=true method=GET path=/hello
21:02:24.884 request_id=fc06cbd2-b8b6-4257-801d-89253ed83962  <metrics>
21:02:24.884 request_id=fc06cbd2-b8b6-4257-801d-89253ed83962  at=finish instrumentation=true method=GET path=/hello elapsed=1.387 status=200

Metrics

Plexy provides some helper functions for taking metric measurements and outputting those metrics to the logs.

Counts

Plexy.Logger.count(metric_name, count) will log the given metric as a count for easy graphing in Librato.

Measures

Plexy.Logger.measure(metric_name, 123) expects a time in milliseconds and logs it as the given metric name.

Plexy.Logger.measure(metric_name, func) will measure the amount of time in milliseconds required to run the given function and logs it as the given metric name. This also returns the value of the given function. It also adds .ms to the metric in case you forget.

Plexy.Logger.measure(:fast, func)
# logs => measure#plexy.fast.ms=123

Plexy.Logger.measure("fast.ms", func)
# logs => measure#my_app.fast.ms=123

Configuring logging

You may need to configure your logging slightly differently, but in general, this pattern will help you create l2met-compatible loglines with UTC times and the Request ID on each line. In config/config.exs:

config :logger,
  utc_log: true

config :logger, :console,
  format: "$time $metadata $message\n",
  metadata: [:request_id]

Make sure that the Plexy.RequestId plug is included in your Elixir app per the Installation instructions, and you will have the request_id in the log metadata.

By default Plexy looks for an ENV variable named APP_NAME and will then fall back to plexy if it is not provided. This value is used for metrics logging.

Plexy.Logger.measure(:fast, 123)
# logs => measure#plexy.fast=123

# APP_NAME env set to "my_app"
Plexy.Logger.measure(:fast, 123)
# logs => measure#my_app.fast=123

If you would like to use a different env var for the app name you can set it.

# config/config.exs
config :plexy,
  app_name: {:system, "HEROKU_APP_NAME"}

# HEROKU_APP_NAME env set to "much_amazing"
Plexy.Logger.measure(:fast, 123)
# logs => measure#much_amazing.fast=123

# or with a default
# config/config.exs
config, :plexy,
  app_name: {:system, "HEROKU_APP_NAME", "such_wow"}

# HEROKU_APP_NAME env is not set
Plexy.Logger.measure(:fast, 123)
# logs => measure#such_wow.fast=123

Configuring exception reporting

We recommend Rollbax as it lives in your logging backends pipeline. This means that the params retracted by the Plexy Redactor won't ever show up in Rollbar. To hide certain keys from your Rollbar reporting, see the next section.

Protecting secrets from appearing in logs or Rollbar

A common pain point for production systems can be inadvertent leaks of secrets to log lines or to exception reporters like Rollbar. While each app will have different values that it considers secret, and how much about a customer or end-user can be logged will depend on the industry, we have provided a generic way to redact certain keys from appearing in logs or being passed through the logging backend pipeline to Rollbax.

To use it, add this to config/config.exs:

 config :plexy, :logger,
   redactors: [
     {Plexy.Logger.SimpleRedactor, [
       redact: ["username"],
       filter: ["password"]
     ]}
   ]

You can also write your own Redactor module and configure it here. The Redactor runs before the data is passed to each logging backend in Plexy.Logger.

Keys that appear in the redact list will appear with the value REDACTED in logs. Keys that appear in the filter list will cause the entire logline to be redacted from the record. Examples:

iex> SimpleRedactor.run("username=bob", redact: ["username"])
{:cont, "username=REDACTED"}
iex> SimpleRedactor.run("password=mysecred", filter: ["password"])
{:cont, ""}

Copyright and License

Created at Heroku by:

• @Adovenmuehle
• @blackfist
• @joshwlewis
• @kennyp
• @mathias

Copyright (c) 2019 maxbeizer

This work is free. You can redistribute it and/or modify it under the terms of the MIT License. See the LICENSE.md file for more details.