prop/test/microwaveprop/logger_format_test.exs
Graham McIntire 52a32032a3
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.
2026-04-21 14:17:54 -05:00

59 lines
2.1 KiB
Elixir

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