diff --git a/backlog/tasks/ml-158 - Force-production-logs-to-single-line-format.md b/backlog/completed/ml-158 - Force-production-logs-to-single-line-format.md similarity index 82% rename from backlog/tasks/ml-158 - Force-production-logs-to-single-line-format.md rename to backlog/completed/ml-158 - Force-production-logs-to-single-line-format.md index 5436e974..115a15aa 100644 --- a/backlog/tasks/ml-158 - Force-production-logs-to-single-line-format.md +++ b/backlog/completed/ml-158 - Force-production-logs-to-single-line-format.md @@ -1,15 +1,24 @@ --- id: ML-158 title: Force production logs to single-line format -status: To Do +status: Done assignee: [] created_date: '2026-05-03 13:51' -updated_date: '2026-05-04 08:18' +updated_date: '2026-05-04 13:43' labels: - ready dependencies: [] references: - 'backlog://documents/doc-3' +modified_files: + - mix.exs + - config/config.exs + - config/prod.exs + - lib/music_library/application.ex + - lib/music_library/logger/single_line_formatter.ex + - test/music_library/logger/single_line_formatter_test.exs + - docs/production-infrastructure.md + - docs/architecture.md priority: medium --- @@ -21,12 +30,12 @@ When running in production, logs spanning multiple lines create issues — they ## Acceptance Criteria -- [ ] #1 HTTP request logs (GET /path + Sent 200) appear as a single logfmt line in production -- [ ] #2 LiveView socket connection logs (CONNECTED TO Phoenix.LiveView.Socket) appear as a single line -- [ ] #3 No log message in production output spans multiple physical lines — all newlines are escaped as \\n -- [ ] #4 Existing metadata (request_id, etc.) is preserved in log output -- [ ] #5 Stack traces from errors/exceptions are escaped to single line -- [ ] #6 Dev environment logging is unchanged and still uses multi-line format for readability +- [x] #1 HTTP request logs (GET /path + Sent 200) appear as a single logfmt line in production +- [x] #2 LiveView socket connection logs (CONNECTED TO Phoenix.LiveView.Socket) appear as a single line +- [x] #3 No log message in production output spans multiple physical lines — all newlines are escaped as \\n +- [x] #4 Existing metadata (request_id, etc.) is preserved in log output +- [x] #5 Stack traces from errors/exceptions are escaped to single line +- [x] #6 Dev environment logging is unchanged and still uses multi-line format for readability ## Implementation Plan @@ -306,3 +315,60 @@ No manual production changes required. All configuration is in `config/prod.exs` **Rollback**: Revert to previous commit. No data migration needed. + +## Final Summary + + +## Implementation Summary + +### What was done + +#### Step 0: Pre-implementation verification +- Confirmed Phoenix.Logger fires 4 events at `:info`+ level (endpoint start/stop, socket_connected, error_rendered) — matches plan assumptions +- Confirmed Logster v2 handles `[:phoenix, :socket_connected]` — **skipped Step 4** (custom telemetry handler unnecessary) + +#### Step 1: Added Logster dependency +- `mix.exs`: `{:logster, "~> 2.0.0-rc.5"}` + +#### Step 2: Disabled Phoenix.Logger in prod +- `config/prod.exs`: `config :phoenix, :logger, false` + +#### Step 3: Configured Logster with environment-conditional attach +- `config/config.exs`: `config :music_library, :single_line_logging, false` +- `config/prod.exs`: `config :music_library, :single_line_logging, true` +- `config/prod.exs`: Logster config with `extra_fields: [:request_id]` and parameter filtering +- `lib/music_library/application.ex`: conditional `Logster.attach_phoenix_logger()` when `single_line_logging` is true + +#### Step 4: Skipped (Logster v2 handles `[:phoenix, :socket_connected]`) + +#### Step 5-6: Created custom Logger.Formatter as safety net +- `lib/music_library/logger/single_line_formatter.ex`: Implements `format/4` callback, replaces embedded `\n` with escaped `\\n`, handles string/iolist/report messages, preserves metadata +- `config/prod.exs`: formatter configured as `{MusicLibrary.Logger.SingleLineFormatter, :format}` with `metadata: [:request_id]` + +#### Step 7: Codebase audit +- Searched for Logger calls with embedded `\n` — none found +- Multi-line Logger calls in source all produce single-line output (string concatenation without actual newlines) +- Custom formatter handles any remaining cases from OTP/Elixir internals + +#### Step 8: Tests +- `test/music_library/logger/single_line_formatter_test.exs`: 13 tests covering newline replacement, iolist handling, metadata preservation, single-line output, dev/test config verification +- All 931 project tests pass + +#### Step 9: OTP release verification +- `MIX_ENV=prod mix release` builds successfully +- sys.config confirms: `phoenix logger: false`, `single_line_logging: true`, Logster config, custom formatter tuple, logster application included + +#### Step 10: Documentation +- `docs/production-infrastructure.md`: Added "Logging" section under Monitoring & Observability +- `docs/architecture.md`: Added `MusicLibrary.Logger.SingleLineFormatter` to Business Logic Modules, Logster note under Supervision Tree, and Web Utility Modules note + +### Files changed +- `mix.exs` — added logster dependency +- `config/config.exs` — added `single_line_logging: false` +- `config/prod.exs` — 4 config additions (phoenix logger disable, flag, logster, formatter) +- `lib/music_library/application.ex` — conditional Logster attach +- `lib/music_library/logger/single_line_formatter.ex` — new module +- `test/music_library/logger/single_line_formatter_test.exs` — new test file +- `docs/production-infrastructure.md` — Logging section +- `docs/architecture.md` — module entries + diff --git a/config/config.exs b/config/config.exs index 99d3b284..6180a401 100644 --- a/config/config.exs +++ b/config/config.exs @@ -97,6 +97,8 @@ config :tailwind, cd: Path.expand("..", __DIR__) ] +config :music_library, :single_line_logging, false + # Configures Elixir's Logger config :logger, :default_formatter, format: "$time $metadata[$level] $message\n", diff --git a/config/prod.exs b/config/prod.exs index 3718c3fd..3e75eb0e 100644 --- a/config/prod.exs +++ b/config/prod.exs @@ -11,6 +11,19 @@ config :music_library, MusicLibraryWeb.Endpoint, # Do not print debug messages in production config :logger, level: :info +# Force single-line log output +config :phoenix, :logger, false + +config :music_library, :single_line_logging, true + +config :logster, + extra_fields: [:request_id], + filter_parameters: Application.get_env(:phoenix, :filter_parameters, ["password"]) + +config :logger, :default_formatter, + format: {MusicLibrary.Logger.SingleLineFormatter, :format}, + metadata: [:request_id, :pid] + config :music_library, monitoring_routes: true config :error_tracker, enabled: true diff --git a/docs/architecture.md b/docs/architecture.md index a5998cc0..73e557dd 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -42,6 +42,9 @@ MusicLibrary.Application (one_for_one) └── MusicLibraryWeb.Endpoint ``` +Logster v2 (production-only) is attached as a telemetry handler via `application.ex` +when `single_line_logging` is `true` — not a supervised process. + --- ## Database & Repos @@ -145,6 +148,7 @@ Last.fm schemas (separate, not Ecto-persisted to main DB): | `MusicLibrary.Mailer` | Swoosh mailer (Mailgun in prod, local adapter in dev) | | `FormatNumber` | Number formatting utility | | `QueryReporter` | Dev-only Ecto telemetry reporter: captures executed SQL to a log file with interpolated params, source locations, and timing. Activated at runtime via `start/1` / `stop/0` | +| `MusicLibrary.Logger.SingleLineFormatter` | Production-only Logger.Formatter safety net: replaces embedded newlines (`\n`) with escaped `\\n` in all log messages, ensuring every physical log line is exactly one log event | --- @@ -327,6 +331,7 @@ All authenticated routes live inside a single `live_session` with three `on_moun | `LiveHelpers.Params` | URL query param parsing: pagination, search query, sort order, display mode, fallback index | | `LiveHelpers.IndexActions` | Shared index page logic (search, pagination, import, delete, display mode) for Collection/Wishlist index pages, parameterized by config map | | `LiveHelpers.RecordActions` | Shared record action handlers (refresh cover, genres, embeddings, MusicBrainz data) for Collection/Wishlist show pages | +| — | Logster v2 handles `[:phoenix, :socket_connected]` telemetry — not a custom module | ### Controllers diff --git a/docs/production-infrastructure.md b/docs/production-infrastructure.md index b0b8ca12..1353b7c0 100644 --- a/docs/production-infrastructure.md +++ b/docs/production-infrastructure.md @@ -196,6 +196,47 @@ ERL_FLAGS: `+JPperf true` (JIT performance monitoring). `GET /health` — queries the main database, returns 200 or 500. Used by Docker health checks and post-deploy verification. +### Logging + +Production logs are configured for single-line output so every physical log line +corresponds to exactly one log event. This makes log files reliably filterable with +line-oriented tools (grep, tail, sort) and enables deterministic reverse-order reading. + +Three layers work together: + +1. **Logster v2** — Replaces `Phoenix.Logger` for HTTP request and LiveView socket + telemetry. Merges `GET + Sent` into a single logfmt line with `method`, `path`, + `status`, `duration`, and `request_id` fields. Handles `[:phoenix, :socket_connected]` + telemetry, flattening the multi-line handshake output into one line. + +2. **Custom formatter** (`MusicLibrary.Logger.SingleLineFormatter`) — Safety net that + replaces any remaining embedded newlines (`\n`) with escaped `\\n` in ALL log + messages. Catches stack traces, Erlang runtime messages, and any multi-line strings + that Logster does not cover. Configured in `config/prod.exs`. + +3. **Config flag** (`single_line_logging`) — Boolean in `config/config.exs` (default + `false`) and overridden to `true` in `config/prod.exs`. Controls `Logster.attach_phoenix_logger()` + in `application.ex`. Dev/test environments keep the default multi-line format for readability. + +Configuration summary: + +```elixir +# config/prod.exs +config :phoenix, :logger, false +config :music_library, :single_line_logging, true + +config :logster, + extra_fields: [:request_id], + filter_parameters: Application.get_env(:phoenix, :filter_parameters, ["password"]) + +config :logger, :default_formatter, + format: {MusicLibrary.Logger.SingleLineFormatter, :format}, + metadata: [:request_id, :pid] +``` + +Dev environment retains the default `"$time $metadata[$level] $message\n"` format with +`Phoenix.Logger` active. + ### Error tracking `ErrorTracker` with email notifications via Mailgun: diff --git a/lib/music_library/application.ex b/lib/music_library/application.ex index b031ef49..d0a29e1d 100644 --- a/lib/music_library/application.ex +++ b/lib/music_library/application.ex @@ -30,6 +30,10 @@ defmodule MusicLibrary.Application do MusicLibraryWeb.Endpoint ] + if Application.fetch_env!(:music_library, :single_line_logging) do + Logster.attach_phoenix_logger() + end + # See https://hexdocs.pm/elixir/Supervisor.html # for other strategies and supported options opts = [strategy: :one_for_one, name: MusicLibrary.Supervisor] diff --git a/lib/music_library/logger/single_line_formatter.ex b/lib/music_library/logger/single_line_formatter.ex new file mode 100644 index 00000000..5f467f11 --- /dev/null +++ b/lib/music_library/logger/single_line_formatter.ex @@ -0,0 +1,123 @@ +defmodule MusicLibrary.Logger.SingleLineFormatter do + @moduledoc """ + Production-only safety net for single-line log output. + + Replaces any embedded newline characters (`\\n`) in log messages with + escaped `\\\\n` so every physical log line corresponds to exactly one + log event. This makes log files reliably filterable with line-oriented + tools (grep, tail, sort) and enables deterministic reverse-order + reading. + + ## Design + + The formatter is configured **only in `config/prod.exs`** via: + + config :logger, :default_formatter, + format: {MusicLibrary.Logger.SingleLineFormatter, :format}, + metadata: [:request_id, :pid] + + Developers continue to see multi-line logs for readability. + Logster v2 handles HTTP-request and LiveView-socket telemetry; + this module acts as the universal safety net for anything Logster + does not cover (e.g. stack traces emitted by the Erlang runtime). + """ + + # Elixir Logger.Formatter calls `apply(mod, fun, [level, msg, ts, md])` + # where `msg` is the chardata from `format_event/2`. + # + # We return a flat binary (valid IO.chardata) so callers can always + # convert it with `IO.chardata_to_string/1`. + + @doc """ + Formats a log event as a single line. + + Returns a binary ending with exactly one newline character. + """ + @spec format(atom(), IO.chardata(), Logger.Formatter.date_time_ms(), keyword()) :: IO.chardata() + def format(level, message, timestamp, metadata) do + cleaned = message |> flatten_message() |> escape_newlines() + "#{format_time(timestamp)} #{format_metadata(metadata)}[#{level}] #{cleaned}\n" + end + + # -- helpers --------------------------------------------------------------- + + defp flatten_message(message) when is_binary(message), do: message + + defp flatten_message(message) when is_list(message) do + IO.chardata_to_string(message) + rescue + UnicodeConversionError -> inspect(message) + end + + defp flatten_message(other), do: inspect(other) + + defp escape_newlines(string), do: String.replace(string, "\n", "\\n") + + # Match the standard Logger.Formatter.format_time/1 output: "HH:MM:SS.sss" + defp format_time({_date, {hh, mi, ss, ms}}) do + [pad2(hh), ?:, pad2(mi), ?:, pad2(ss), ?., pad3(ms)] + |> IO.iodata_to_binary() + end + + defp pad2(int) when int < 10, do: [?0, Integer.to_string(int)] + defp pad2(int), do: Integer.to_string(int) + + defp pad3(int) when int < 10, do: [?0, ?0, Integer.to_string(int)] + defp pad3(int) when int < 100, do: [?0, Integer.to_string(int)] + defp pad3(int), do: Integer.to_string(int) + + # Format metadata as "key=value " pairs, matching the standard Logger formatter. + defp format_metadata([]), do: "" + + defp format_metadata(metadata) do + case metadata |> build_meta_pairs() |> Enum.reject(&is_nil/1) do + [] -> "" + pairs -> Enum.join(pairs) <> " " + end + end + + defp build_meta_pairs(metadata) do + Enum.map(metadata, fn {key, value} -> format_meta_pair(key, value) end) + end + + defp format_meta_pair(:request_id, value), do: meta_string("request_id", value) + defp format_meta_pair(:pid, value), do: meta_string("pid", value) + defp format_meta_pair(:module, value), do: meta_string("module", value) + defp format_meta_pair(:function, value), do: meta_string("function", value) + defp format_meta_pair(:line, value), do: meta_string("line", value) + defp format_meta_pair(:domain, value), do: meta_domain(value) + defp format_meta_pair(key, value), do: "#{key}=#{inspect(value)} " + + defp meta_string(_key, nil), do: nil + + defp meta_string(key, value) when is_binary(value) do + "#{key}=#{value} " + end + + defp meta_string(key, value) when is_integer(value) do + "#{key}=#{value} " + end + + defp meta_string(key, value) when is_atom(value) do + "#{key}=#{value} " + end + + defp meta_string(key, value) when is_pid(value) do + "#{key}=#{inspect(value)} " + end + + defp meta_string(key, value) do + "#{key}=#{value} " + end + + defp meta_domain(nil), do: nil + + defp meta_domain([head | tail]) when is_atom(head) do + domain = Enum.map_intersperse([head | tail], ".", &Atom.to_string/1) + "domain=#{domain} " + end + + defp meta_domain(other) do + "domain=#{other} " + end +end diff --git a/mix.exs b/mix.exs index 90c0757b..75d75227 100644 --- a/mix.exs +++ b/mix.exs @@ -172,6 +172,7 @@ defmodule MusicLibrary.MixProject do # Prod error/perf tooling {:error_tracker, "~> 0.9"}, + {:logster, "~> 2.0.0-rc.5"}, {:phoenix_live_dashboard, "~> 0.8.3"}, {:recon, "~> 2.5"}, {:telemetry_metrics, "~> 1.0"}, diff --git a/mix.lock b/mix.lock index fc251890..5ac530d7 100644 --- a/mix.lock +++ b/mix.lock @@ -38,6 +38,7 @@ "lazy_html": {:hex, :lazy_html, "0.1.11", "136c8e9cd616b4f4e9c1562daa683880891120b759606dc4c3b6b18058ba5d79", [:make, :mix], [{:cc_precompiler, "~> 0.1", [hex: :cc_precompiler, repo: "hexpm", optional: false]}, {:elixir_make, "~> 0.9.0", [hex: :elixir_make, repo: "hexpm", optional: false]}, {:fine, "~> 0.1.0", [hex: :fine, repo: "hexpm", optional: false]}], "hexpm", "3b1be592929c31eca1a21673d25696e5c14cddfe922d9d1a3e3b48be4163883b"}, "live_debugger": {:hex, :live_debugger, "1.0.0", "0bbcbdcb3b40b6862b6dfbb76579e7832e2787fee643031e5958f597def6fb32", [:mix], [{:file_system, "~> 1.0", [hex: :file_system, repo: "hexpm", optional: false]}, {:igniter, ">= 0.5.40 and < 1.0.0-0", [hex: :igniter, repo: "hexpm", optional: true]}, {:phoenix, "~> 1.7", [hex: :phoenix, repo: "hexpm", optional: false]}, {:phoenix_live_view, ">= 1.1.7 and < 2.0.0-0", [hex: :phoenix_live_view, repo: "hexpm", optional: false]}], "hexpm", "b80f5d9db874d3270eb534738a10982b2b4ce55d58f94544e43b4a36111585fc"}, "live_toast": {:hex, :live_toast, "0.8.0", "d7e24801a9a966d8e48872767ac33c50fc14640ac5272128becfc534fabd99b7", [:mix], [{:ecto, ">= 3.11.0", [hex: :ecto, repo: "hexpm", optional: false]}, {:gettext, ">= 0.26.2", [hex: :gettext, repo: "hexpm", optional: false]}, {:jason, "~> 1.4", [hex: :jason, repo: "hexpm", optional: false]}, {:phoenix, ">= 1.7.19", [hex: :phoenix, repo: "hexpm", optional: false]}, {:phoenix_live_view, ">= 1.0.0", [hex: :phoenix_live_view, repo: "hexpm", optional: false]}], "hexpm", "7e64435131b7731698908d59f7ba9f5092df8a3720814f26edf57e99d97a803c"}, + "logster": {:hex, :logster, "2.0.0-rc.5", "5ae9e58b15f03cbe1f71203808ed0db6b0a2b60c0dbd8f4ed76d1b769ec9d440", [:mix], [{:jason, "~> 1.1", [hex: :jason, repo: "hexpm", optional: true]}, {:plug, "~> 1.0", [hex: :plug, repo: "hexpm", optional: false]}], "hexpm", "dddafb22aabbbd7dbef83356d3de66b564a894e19615b049ca1b704a59a032ba"}, "lumis": {:hex, :lumis, "0.5.0", "1d505ff56fede334cf0de78bace0b00433edddb848f4b1affbcc0dc2234cda2a", [:mix], [{:nimble_options, "~> 1.0", [hex: :nimble_options, repo: "hexpm", optional: false]}, {:rustler, "~> 0.29", [hex: :rustler, repo: "hexpm", optional: true]}, {:rustler_precompiled, "~> 0.6", [hex: :rustler_precompiled, repo: "hexpm", optional: false]}], "hexpm", "142a7aae2a22169a389cf70a6a71426092bc541abe699aab9eef31b36e972cb2"}, "mdex": {:hex, :mdex, "0.12.2", "e5f7a62543a7580f3ff55dc2f2953b0d0e74b4327d77d3710946eb1bc9a9b569", [:mix], [{:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: false]}, {:lumis, "~> 0.1", [hex: :lumis, repo: "hexpm", optional: false]}, {:nimble_options, "~> 1.0", [hex: :nimble_options, repo: "hexpm", optional: false]}, {:nimble_parsec, "~> 1.0", [hex: :nimble_parsec, repo: "hexpm", optional: false]}, {:phoenix_live_view, "~> 1.0", [hex: :phoenix_live_view, repo: "hexpm", optional: true]}, {:rustler, "~> 0.32", [hex: :rustler, repo: "hexpm", optional: true]}, {:rustler_precompiled, "~> 0.7", [hex: :rustler_precompiled, repo: "hexpm", optional: false]}], "hexpm", "72cfea060dc9135d66149feb506c13db76da7d3303f3276493bb34482df8f340"}, "mime": {:hex, :mime, "2.0.7", "b8d739037be7cd402aee1ba0306edfdef982687ee7e9859bee6198c1e7e2f128", [:mix], [], "hexpm", "6171188e399ee16023ffc5b76ce445eb6d9672e2e241d2df6050f3c771e80ccd"}, diff --git a/test/music_library/logger/single_line_formatter_test.exs b/test/music_library/logger/single_line_formatter_test.exs new file mode 100644 index 00000000..3759cbb8 --- /dev/null +++ b/test/music_library/logger/single_line_formatter_test.exs @@ -0,0 +1,143 @@ +defmodule MusicLibrary.Logger.SingleLineFormatterTest do + use ExUnit.Case, async: true + + alias MusicLibrary.Logger.SingleLineFormatter + + @ts {{2024, 1, 15}, {14, 30, 45, 123}} + + describe "environment configuration" do + test "single_line_logging is disabled in dev/test" do + refute Application.fetch_env!(:music_library, :single_line_logging) + end + + test "default formatter is the standard pattern (not our custom module)" do + default_formatter = Application.get_env(:logger, :default_formatter, []) + + refute match?({MusicLibrary.Logger.SingleLineFormatter, _}, default_formatter[:format]) + assert is_binary(default_formatter[:format]) + end + + test "Phoenix.Logger is not disabled in dev/test" do + phoenix_logger = Application.get_env(:phoenix, :logger, true) + assert phoenix_logger + end + end + + describe "format/4" do + test "replaces embedded newlines with escaped \\n" do + result = + SingleLineFormatter.format(:error, "line1\nline2\nline3", @ts, []) + |> IO.chardata_to_string() + + assert result =~ "line1\\nline2\\nline3" + refute String.contains?(result, "\nline2") + assert String.ends_with?(result, "\n") + end + + test "messages without newlines pass through unchanged" do + result = + SingleLineFormatter.format(:info, "hello world", @ts, []) + |> IO.chardata_to_string() + + assert result =~ "hello world" + assert String.ends_with?(result, "\n") + end + + test "handles iolist input" do + iolist = ~c"hello\nworld" + + result = + SingleLineFormatter.format(:error, iolist, @ts, []) + |> IO.chardata_to_string() + + assert result =~ "hello\\nworld" + assert String.ends_with?(result, "\n") + end + + test "preserves metadata in output" do + result = + SingleLineFormatter.format(:info, "test message", @ts, request_id: "abc123") + |> IO.chardata_to_string() + + assert result =~ "request_id=abc123" + end + + test "handles empty messages" do + result = + SingleLineFormatter.format(:info, "", @ts, []) + |> IO.chardata_to_string() + + assert String.ends_with?(result, "\n") + assert result =~ "[info]" + end + + test "handles nil metadata" do + result = + SingleLineFormatter.format(:info, "msg", @ts, []) + |> IO.chardata_to_string() + + assert result =~ "[info] msg" + end + + test "output is a single line (no unescaped newlines in the message part)" do + result = + SingleLineFormatter.format(:error, "a\nb\nc", @ts, []) + |> IO.chardata_to_string() + + lines = String.split(result, "\n", trim: true) + assert length(lines) == 1 + end + + test "includes level and timestamp" do + result = + SingleLineFormatter.format(:warning, "caution", @ts, []) + |> IO.chardata_to_string() + + assert result =~ "[warning]" + assert result =~ "14:30:45.123" + end + + test "handles multiple metadata keys" do + result = + SingleLineFormatter.format(:info, "msg", @ts, request_id: "req1", pid: self()) + |> IO.chardata_to_string() + + assert result =~ "request_id=req1" + end + + test "pipe character in message is preserved" do + result = + SingleLineFormatter.format(:info, "status=200|duration=10ms", @ts, []) + |> IO.chardata_to_string() + + assert result =~ "status=200|duration=10ms" + end + + test "handles non-binary, non-list message via inspect fallback" do + result = + SingleLineFormatter.format(:info, %{key: "value"}, @ts, []) + |> IO.chardata_to_string() + + assert result =~ "%{key: \"value\"}" + end + + test "handles invalid iolist gracefully (UnicodeConversionError)" do + # Surrogate codepoint 0xD800 is not valid Unicode + result = + SingleLineFormatter.format(:error, [0xD800], @ts, []) + |> IO.chardata_to_string() + + assert result =~ "[error]" + assert String.ends_with?(result, "\n") + end + + test "unknown metadata keys are included via inspect" do + result = + SingleLineFormatter.format(:info, "msg", @ts, custom_key: "custom_val") + |> IO.chardata_to_string() + + assert result =~ "custom_key=" + assert result =~ "custom_val" + end + end +end