diff --git a/config/runtime.exs b/config/runtime.exs index 58044bc1..68352d9b 100644 --- a/config/runtime.exs +++ b/config/runtime.exs @@ -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` / diff --git a/mix.exs b/mix.exs index 6f207a99..592aba30 100644 --- a/mix.exs +++ b/mix.exs @@ -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}, diff --git a/mix.lock b/mix.lock index eed32f19..7beb0699 100644 --- a/mix.lock +++ b/mix.lock @@ -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"}, diff --git a/test/microwaveprop/logger_format_test.exs b/test/microwaveprop/logger_format_test.exs new file mode 100644 index 00000000..30b148a2 --- /dev/null +++ b/test/microwaveprop/logger_format_test.exs @@ -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