Friday, March 26, 2021

Elixir Systemd Logging

If you run an Elixir application as a Linux service with systemd, you'll probably find that logging works pretty well out of the box. By default, Elixir uses the Console logger backend, which sends all log messages to stdout. And with systemd services, by default all stdout messages are sent to journald.

This means you can view your application's logs easily via the journalctl command. For example, you can "tail" your app's logs with a command like this (if the systemd unit for the app was named my_app):

journalctl -u my_app -f

You can also configure systemd to send your app's stdout to a custom log file instead of journald, using the StandardOutput directive. You can add that directive to the [Service] section of a systemd unit file (for example, to log to a custom /var/log/my_app.log):

# /etc/systemd/system/my_app.service [Service] ExecStart=/srv/my_app/bin/my_app start ExecStop=/srv/my_app/bin/my_app stop StandardOutput=append:/var/log/my_app.log

Problems

If you collect and ship your log messages off to a centralized log service (like AWS CloudWatch, Google Cloud Logging, Azure Monitor, Splunk, Sumologic, Elasticsearch, Loggly, Datadog, New Relic, etc), you'll find two problems with this, however:

  1. Multi-line messages are broken up into a separate log entry for each line
  2. Log level/priority is lost

You can add some steps further down your logging pipeline to try to correct this, but the easiest way to fix it is at the source: Replace the default Console logger with the ExSyslogger backend.

Here's how you'd do that with a Phoenix web app:

1. Add the ex_syslogger dependency

First, add the ex_syslogger library as a dependency to your mix.exs file:

# mix.exs defp deps do [ {:ex_syslogger, "~> 1.5"} ] end

2. Register the ex_syslogger backend

Update the root config :logger options in your config/prod.exs file to register the ExSyslogger backend under the name :ex_syslogger:

# config/prod.exs # Do not print debug messages in production config :logger, level: :info config :logger, level: :info, backends: [{ExSyslogger, :ex_syslogger}]

Note that the :ex_syslogger name isn't special — you can call it whatever you want. It just has to match the name you use in the next section:

3. Configure the ex_syslogger backend

Now add config :logger, :ex_syslogger options to your config/config.exs file to configure the backend named :ex_syslogger that you registered above. I'd suggest just duplicating the configuration you already have for the default :console backend, plus setting the syslog APP-NAME field to your app's name via the ident option:

# config/config.exs # Configures Elixir's Logger config :logger, :console, format: "$time $metadata[$level] $message\n", metadata: [:request_id] config :logger, :ex_syslogger, format: "$time $metadata[$level] $message\n", metadata: [:request_id], ident: "my_app"

Result

Now when you compile your app with MIX_ENV=prod and run it as a systemd service, journald will automatically handle multi-line messages and log levels/priorities correctly. Furthermore, you can use any generic syslog collector to ship log entries to your log service as soon as they occur — with multi-line messages and log levels intact.

For example, when using the default Console logger, an error message from a Phoenix web app would have been displayed like this by journalctl:

$ journalctl -u my_app -f Mar 26 18:21:10 foo my_app[580361]: 18:21:10.337 request_id=Fm_3dFhPMtEHARkAAALy [info] Sent 500 in 16ms Mar 26 18:21:10 foo my_app[580361]: 18:21:10.345 [error] #PID<0.4149.0> running MyAppWeb.Endpoint (connection #PID<0.4148.0>, stream id 1) terminated Mar 26 18:21:10 foo my_app[580361]: Server: foo.example.com:443 (https) Mar 26 18:21:10 foo my_app[580361]: Request: GET /test/error Mar 26 18:21:10 foo my_app[580361]: ** (exit) an exception was raised: Mar 26 18:21:10 foo my_app[580361]: ** (RuntimeError) test runtime error Mar 26 18:21:10 foo my_app[580361]: (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:9: MyAppWeb.TestController.error/2 Mar 26 18:21:10 foo my_app[580361]: (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:1: MyAppWeb.TestController.action/2 Mar 26 18:21:10 foo my_app[580361]: (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:1: MyAppWeb.TestController.phoenix_controller_pipeline/2 Mar 26 18:21:10 foo my_app[580361]: (phoenix 1.5.8) lib/phoenix/router.ex:352: Phoenix.Router.__call__/2 Mar 26 18:21:10 foo my_app[580361]: (my_app 0.1.0) lib/my_app_web/endpoint.ex:1: MyAppWeb.Endpoint.plug_builder_call/2 Mar 26 18:21:10 foo my_app[580361]: (my_app 0.1.0) lib/my_app_web/endpoint.ex:1: MyAppWeb.Endpoint.call/2 Mar 26 18:21:10 foo my_app[580361]: (phoenix 1.5.8) lib/phoenix/endpoint/cowboy2_handler.ex:65: Phoenix.Endpoint.Cowboy2Handler.init/4 Mar 26 18:21:10 foo my_app[580361]: (cowboy 2.8.0) /srv/my_app/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2

But with ExSyslogger in place, you'll now see this (where the full error message is captured as a single log entry, and is recognized as an error-level message):

$ journalctl -u my_app -f Mar 26 18:21:10 foo my_app[580361]: 18:21:10.337 request_id=Fm_3dFhPMtEHARkAAALy [info] Sent 500 in 16ms Mar 26 18:21:10 foo my_app[580361]: 18:21:10.345 [error] #PID<0.4149.0> running MyAppWeb.Endpoint (connection #PID<0.4148.0>, stream id 1) terminated Server: foo.example.com:443 (https) Request: GET /test/error ** (exit) an exception was raised: ** (RuntimeError) test runtime error (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:9: MyAppWeb.TestController.error/2 (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:1: MyAppWeb.TestController.action/2 (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:1: MyAppWeb.TestController.phoenix_controller_pipeline/2 (phoenix 1.5.8) lib/phoenix/router.ex:352: Phoenix.Router.__call__/2 (my_app 0.1.0) lib/my_app_web/endpoint.ex:1: MyAppWeb.Endpoint.plug_builder_call/2 (my_app 0.1.0) lib/my_app_web/endpoint.ex:1: MyAppWeb.Endpoint.call/2 (phoenix 1.5.8) lib/phoenix/endpoint/cowboy2_handler.ex:65: Phoenix.Endpoint.Cowboy2Handler.init/4 (cowboy 2.8.0) /srv/my_app/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2

And as a side note, you can use journalctl to view just error-level messages and above via the --priority=err flag (-p3 for short):

journalctl -u my_app -p3

Monday, March 8, 2021

D3v6 Pan and Zoom

Since D3 version 3 it's been really easy to add panning and zooming to custom visualizations, allowing the user to scroll the SVG canvas vertically and horizontally by clicking and dragging the mouse cursor around the canvas, and to scale the canvas larger and smaller by spinning the mouse wheel.

Simplest way

For the simplest case, all you need is to apply the d3.zoom() behavior to your root svg element. This is how you do it with D3 version 6 (d3.v6.js):

<svg id="viz1" width="300" height="300" style="background:#ffc"> <circle cx="50%" cy="50%" r="25%" fill="#69c" /> </svg> <script> const svg = d3 .select('#viz1') .call(d3.zoom().on('zoom', ({ transform }) => svg.attr('transform', transform))) </script>

It'll work like the following:

Smoothest way

In most cases, however, you'll get smoother behavior by adding some group (<g>) elements to wrap your main visualization elements. If you're starting with a structure like the following, where you've got a .canvas group element containing the main content you want to pan and zoom:

<svg id="viz2" width="300" height="300"> <g class="canvas" transform="translate(150,150)"> <circle cx="0" cy="0" r="25%" fill="#69c" /> </g> </svg>

Do this: add one wrapper group element, .zoomed, around the original .canvas group; and a second group element, .bg, around .zoomed; and add a rect inside the .bg group:

<svg id="viz2" width="300" height="300"> <g class="bg"> <rect width="100%" height="100%" fill="#efc" /> <g class="zoomed"> <g class="canvas" transform="translate(150,150)"> <circle cx="0" cy="0" r="25%" fill="#69c" /> </g> </g> </g> </svg>

The rect inside the .bg group will ensure that the user's click-n-drag or mouse wheeling will be captured as long as the mouse pointer is anywhere inside the svg element (without this rect, the mouse would be captured only when the user positions the mouse over a graphical element drawn inside the .bg group — like the circle in this example). For this example, I've set the fill of the rect to a light green-yellow color; but usually you'd just set it to transparent.

Then attach the pan & zoom behavior to the .bg group — but apply the pan & zoom transform to the .zoomed group it contains. This will prevent stuttering when panning, since the .bg group will remain fixed; and it will avoid messing with any transforms or other fancy styling/positioning you already have on your inner .canvas group:

<script> const zoomed = d3.select('#viz2 .zoomed') const bg = d3 .select('#viz2 .bg') .call( d3 // base d3 pan & zoom behavior .zoom() // limit zoom to between 20% and 200% of original size .scaleExtent([0.2, 2]) // apply pan & zoom transform to 'zoomed' element .on('zoom', ({ transform }) => zoomed.attr('transform', transform)) // add 'grabbing' class to 'bg' element when panning; // add 'scaling' class to 'bg' element when zooming .on('start', ({ sourceEvent: { type } }) => { bg.classed(type === 'wheel' ? 'scaling' : 'grabbing', true) }) // remove 'grabbing' and 'scaling' classes when done panning & zooming .on('end', () => bg.classed('grabbing scaling', false)), ) </script>

Finally, set the mouse cursor via CSS when the user positions the pointer over the rect element. The grabbing and scaling classes will be added to the .bg group while the pan or zoom activity is ongoing, via the on('start') and on('end') hooks above:

<style lang="css"> .bg > rect { cursor: move; } .bg.grabbing > rect { cursor: grabbing; } .bg.scaling > rect { cursor: zoom-in; } </style>

When you put it all together, it will work like the following: