feat(logging): structured JSON logs in prod via LOG_FORMAT env var

The ingress + Grafana pipeline parses JSON-formatted log lines; Elixir's
default text formatter was the odd format everywhere else, forcing Loki
to fall back to free-text parsing. Swap the `:default` :logger handler's
formatter to `LoggerJSON.Formatters.Basic` when `LOG_FORMAT=json`.

Defaults: `LOG_FORMAT=text` for dev/test (no behaviour change), `json`
for prod. Whitelisted metadata covers the fields we actually correlate
on — `request_id`, `trace_id`, `worker`, `queue`, `job_id`.

OTP 28 / Elixir 1.19 exposes `Logger.Formatter.new/1` but ships no
JSON encoder of its own, so `logger_json` (~> 7.0) carries the rendering.
The test pokes the formatter directly rather than round-tripping through
ExUnit's capture_log, which replaces the handler and so can't see the
installed formatter's output.
This commit is contained in:
Graham McIntire 2026-04-21 14:16:58 -05:00
parent 02bf34db9e
commit 52a32032a3
No known key found for this signature in database
GPG key ID: F4ABF488E6029E59
4 changed files with 80 additions and 0 deletions

View file

@ -23,6 +23,21 @@ if System.get_env("PHX_SERVER") do
config :microwaveprop, MicrowavepropWeb.Endpoint, server: true
end
# Log format: "text" (default) keeps Elixir's built-in line formatter for
# local/dev use; "json" swaps the :default :logger handler to emit a single
# JSON object per line via `LoggerJSON.Formatters.Basic`. The ingress +
# Grafana pipeline is already JSON-aware, so prod defaults to JSON.
log_format =
System.get_env("LOG_FORMAT") ||
if(config_env() == :prod, do: "json", else: "text")
if log_format == "json" do
formatter =
LoggerJSON.Formatters.Basic.new(metadata: [:request_id, :trace_id, :worker, :queue, :job_id])
:logger.update_handler_config(:default, :formatter, formatter)
end
config :microwaveprop, MicrowavepropWeb.Endpoint, http: [port: String.to_integer(System.get_env("PORT", "4000"))]
# MicrowavepropWeb.Plugs.RemoteIp will only honour `Cf-Connecting-Ip` /

View file

@ -88,6 +88,11 @@ defmodule Microwaveprop.MixProject do
{:opentelemetry_bandit, "~> 0.2"},
{:gettext, "~> 0.26"},
{:jason, "~> 1.2"},
# Structured JSON log formatter plugged into Elixir 1.15+ :logger.
# OTP 28 / Elixir 1.19 ships `Logger.Formatter.new/1` but no built-in
# JSON encoder, so the hex package fills the gap. Prod flips to
# LOG_FORMAT=json; dev/test stay on the default text formatter.
{:logger_json, "~> 7.0"},
{:msgpax, "~> 2.4"},
{:bandit, "~> 1.5"},
{:styler, "~> 1.11", only: [:dev, :test], runtime: false},

View file

@ -41,6 +41,7 @@
"libcluster": {:hex, :libcluster, "3.5.0", "5ee4cfde4bdf32b2fef271e33ce3241e89509f4344f6c6a8d4069937484866ba", [:mix], [{:jason, "~> 1.1", [hex: :jason, repo: "hexpm", optional: false]}, {:telemetry, "~> 1.3", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "ebf6561fcedd765a4cd43b4b8c04b1c87f4177b5fb3cbdfe40a780499d72f743"},
"live_stash": {:hex, :live_stash, "0.1.2", "d67d3670cae453fbc063ddba4602c4e342a16c547d54427b31e57abbbfd28bd2", [:mix], [{:phoenix_live_view, "~> 1.0", [hex: :phoenix_live_view, repo: "hexpm", optional: false]}, {:uniq, "~> 0.6", [hex: :uniq, repo: "hexpm", optional: false]}], "hexpm", "46367a2abdf25c8aa8a854f8f480e3eb3b0a1987040b46893d75cdd90e1a9b24"},
"live_table": {:hex, :live_table, "0.4.1", "26055f78af6295b6d6deefb5ffd31f87b49c8f74cdf65b6dff0da595767ea470", [:mix], [{:ecto, "~> 3.13", [hex: :ecto, repo: "hexpm", optional: false]}, {:ecto_sql, "~> 3.13", [hex: :ecto_sql, repo: "hexpm", optional: false]}, {:igniter, "~> 0.7.0", [hex: :igniter, repo: "hexpm", optional: true]}, {:jason, "~> 1.4", [hex: :jason, repo: "hexpm", optional: false]}, {:nimble_csv, "~> 1.3", [hex: :nimble_csv, repo: "hexpm", optional: false]}, {:oban, "~> 2.20", [hex: :oban, repo: "hexpm", optional: false]}, {:oban_web, "~> 2.11", [hex: :oban_web, repo: "hexpm", optional: false]}, {:phoenix_html, "~> 4.3", [hex: :phoenix_html, repo: "hexpm", optional: false]}, {:phoenix_live_view, "~> 1.1", [hex: :phoenix_live_view, repo: "hexpm", optional: false]}, {:postgrex, ">= 0.0.0", [hex: :postgrex, repo: "hexpm", optional: false]}, {:sutra_ui, "~> 0.3.0", [hex: :sutra_ui, repo: "hexpm", optional: true]}], "hexpm", "2f20a173e6944526607eb5c91196ce0774fc7235bf715bb2ba2d43828965fd9d"},
"logger_json": {:hex, :logger_json, "7.0.4", "e315f2b9a755504658a745f3eab90d88d2cd7ac2ecfd08c8da94d8893965ab5c", [:mix], [{:decimal, ">= 0.0.0", [hex: :decimal, repo: "hexpm", optional: true]}, {:ecto, "~> 3.11", [hex: :ecto, repo: "hexpm", optional: true]}, {:jason, "~> 1.4", [hex: :jason, repo: "hexpm", optional: true]}, {:plug, "~> 1.15", [hex: :plug, repo: "hexpm", optional: true]}, {:telemetry, "~> 1.0", [hex: :telemetry, repo: "hexpm", optional: true]}], "hexpm", "d1369f8094e372db45d50672c3b91e8888bcd695fdc444a37a0734e96717c45c"},
"mime": {:hex, :mime, "2.0.7", "b8d739037be7cd402aee1ba0306edfdef982687ee7e9859bee6198c1e7e2f128", [:mix], [], "hexpm", "6171188e399ee16023ffc5b76ce445eb6d9672e2e241d2df6050f3c771e80ccd"},
"mint": {:hex, :mint, "1.7.1", "113fdb2b2f3b59e47c7955971854641c61f378549d73e829e1768de90fc1abf1", [:mix], [{:castore, "~> 0.1.0 or ~> 1.0", [hex: :castore, repo: "hexpm", optional: true]}, {:hpax, "~> 0.1.1 or ~> 0.2.0 or ~> 1.0", [hex: :hpax, repo: "hexpm", optional: false]}], "hexpm", "fceba0a4d0f24301ddee3024ae116df1c3f4bb7a563a731f45fdfeb9d39a231b"},
"msgpax": {:hex, :msgpax, "2.4.0", "4647575c87cb0c43b93266438242c21f71f196cafa268f45f91498541148c15d", [:mix], [{:plug, "~> 1.0", [hex: :plug, repo: "hexpm", optional: true]}], "hexpm", "ca933891b0e7075701a17507c61642bf6e0407bb244040d5d0a58597a06369d2"},

View file

@ -0,0 +1,59 @@
defmodule Microwaveprop.LoggerFormatTest do
# async: false — we briefly swap the global :default :logger handler's
# formatter and forward its output to a self()-bound IO device so the
# test can capture the JSON-encoded output. Restored on exit.
use ExUnit.Case, async: false
alias LoggerJSON.Formatters.Basic
require Logger
describe "structured JSON formatter" do
setup do
{:ok, handler_cfg} = :logger.get_handler_config(:default)
prev_formatter = handler_cfg.formatter
new_formatter =
Basic.new(metadata: [:request_id, :trace_id, :worker, :queue, :job_id])
:ok = :logger.update_handler_config(:default, :formatter, new_formatter)
on_exit(fn ->
:logger.update_handler_config(:default, :formatter, prev_formatter)
end)
{:ok, formatter: new_formatter}
end
test "Basic formatter encodes an info log as a valid JSON object",
%{formatter: {formatter_mod, formatter_cfg}} do
# Build a `:logger` log event the same shape the handler feeds the
# formatter, then assert the formatter's output is valid JSON with
# the expected message and metadata fields.
log_event = %{
level: :info,
msg: {:string, "hello-json"},
meta: %{
time: :os.system_time(:microsecond),
request_id: "abc-123",
worker: "TestWorker"
}
}
rendered = formatter_mod.format(log_event, formatter_cfg)
payload = rendered |> IO.iodata_to_binary() |> String.trim_trailing("\n")
assert {:ok, decoded} = Jason.decode(payload)
assert decoded["message"] == "hello-json"
assert get_in(decoded, ["metadata", "request_id"]) == "abc-123"
assert get_in(decoded, ["metadata", "worker"]) == "TestWorker"
end
test "swapping the :default handler formatter takes effect" do
# Smoke test that the setup actually attached our JSON formatter
# to the :default handler (i.e. the runtime.exs swap would land).
{:ok, cfg} = :logger.get_handler_config(:default)
assert match?({Basic, _}, cfg.formatter)
end
end
end