From 9ba53f8c86c7cf0072882d39b70e6b4e91c8a360 Mon Sep 17 00:00:00 2001 From: Austin Ziegler Date: Sat, 15 Nov 2025 16:52:03 -0500 Subject: [PATCH 1/2] Add `:formatter` to ExUnit.CaptureLog options Mostly modified `:log_capture_on` handler for ExUnit.CaptureServer to respect a `:formatter` option instead `Logger.default_formatter/1`. Updates were made to documentation and tests to reflect this change. --- lib/ex_unit/lib/ex_unit/capture_log.ex | 14 ++- lib/ex_unit/lib/ex_unit/capture_server.ex | 5 +- lib/ex_unit/test/ex_unit/capture_log_test.exs | 106 ++++++++++++++++++ 3 files changed, 120 insertions(+), 5 deletions(-) diff --git a/lib/ex_unit/lib/ex_unit/capture_log.ex b/lib/ex_unit/lib/ex_unit/capture_log.ex index e8178a9b7b4..1a7b1288df6 100644 --- a/lib/ex_unit/lib/ex_unit/capture_log.ex +++ b/lib/ex_unit/lib/ex_unit/capture_log.ex @@ -44,16 +44,17 @@ defmodule ExUnit.CaptureLog do @compile {:no_warn_undefined, Logger} @type capture_log_opts :: [ - level: Logger.level() | nil + {:level, Logger.level() | nil} + | {:formatter, {module(), term()} | nil} ] @doc """ Captures Logger messages generated when evaluating `fun`. Returns the binary which is the captured output. The captured log - messages will be formatted using `Logger.default_formatter/1`. Any - option, besides the `:level`, will be forwarded as an override to - the default formatter. + messages will be formatted using `Logger.default_formatter/1` by + default. Any option, besides `:level` or `formatter`, will be + forwarded as an override to the default formatter. This function mutes the default logger handler and captures any log messages sent to Logger from the calling processes. It is possible @@ -75,6 +76,11 @@ defmodule ExUnit.CaptureLog do configured in this function, no message will be captured. The behaviour is undetermined if async tests change Logger level. + It is possible to use an alternative log formatter with `:formatter`, + which must be provided as `{module, config}`. If `:formatter` is not + provided, the formatter configuration from `Logger.default_formatter/1` + will be used. + To get the result of the evaluation along with the captured log, use `with_log/2`. """ diff --git a/lib/ex_unit/lib/ex_unit/capture_server.ex b/lib/ex_unit/lib/ex_unit/capture_server.ex index 4ce0bdb45c6..5eb4f4a18b4 100644 --- a/lib/ex_unit/lib/ex_unit/capture_server.ex +++ b/lib/ex_unit/lib/ex_unit/capture_server.ex @@ -75,7 +75,10 @@ defmodule ExUnit.CaptureServer do refs = Map.put(config.log_captures, ref, true) {level, opts} = Keyword.pop(opts, :level) - {formatter_mod, formatter_config} = Logger.default_formatter(opts) + + {formatter_mod, formatter_config} = + Keyword.get_lazy(opts, :formatter, fn -> Logger.default_formatter(opts) end) + true = :ets.insert(@ets, {ref, string_io, level || :all, formatter_mod, formatter_config}) if map_size(refs) == 1 do diff --git a/lib/ex_unit/test/ex_unit/capture_log_test.exs b/lib/ex_unit/test/ex_unit/capture_log_test.exs index 1c61a981c89..7a7352ac3a2 100644 --- a/lib/ex_unit/test/ex_unit/capture_log_test.exs +++ b/lib/ex_unit/test/ex_unit/capture_log_test.exs @@ -143,6 +143,112 @@ defmodule ExUnit.CaptureLogTest do end end + defmodule ReverseFormatter do + def new(options \\ []) do + {_, opts} = Logger.Formatter.new(options) + {__MODULE__, opts} + end + + def format(event, config) do + event + |> reverse() + |> Logger.Formatter.format(config) + end + + defp reverse(event) do + msg = + event + |> Logger.Formatter.format_event(:infinity) + |> to_string() + |> String.reverse() + + %{event | msg: {:string, msg}} + end + end + + describe "with formatter" do + test "log tracking" do + logged = + capture_log([formatter: ReverseFormatter.new()], fn -> + Logger.info("one") + + logged = capture_log([formatter: ReverseFormatter.new()], fn -> Logger.error("one") end) + send(test = self(), {:nested, logged}) + + Logger.warning("two") + + spawn(fn -> + Logger.debug("three") + send(test, :done) + end) + + receive do: (:done -> :ok) + end) + + assert logged + assert logged =~ "[info] eno" + assert logged =~ "[warning] owt" + assert logged =~ "[debug] eerht" + assert logged =~ "[error] eno" + + receive do + {:nested, logged} -> + assert logged =~ "[error] eno" + refute logged =~ "[warning] owt" + end + end + + test "with_log/2: returns the result and the log" do + {result, log} = + with_log([formatter: ReverseFormatter.new()], fn -> + Logger.error("calculating...") + 2 + 2 + end) + + assert result == 4 + assert log =~ "...gnitaluclac" + end + + test "respects the :format, :metadata, and :colors options" do + options = [ + formatter: + ReverseFormatter.new( + format: "$metadata| $message", + metadata: [:id], + colors: [enabled: false] + ) + ] + + assert {4, log} = + with_log(options, fn -> + Logger.info("hello", id: 123) + 2 + 2 + end) + + assert log == "id=123 | olleh" + end + + @tag capture_log: true + test "with_log/2: respect options with capture_log: true" do + {_, opts} = + Logger.Formatter.new( + format: "$metadata| $message", + metadata: [:id], + colors: [enabled: false] + ) + + options = [formatter: {ReverseFormatter, opts}] + + assert {4, log} = + with_log(options, fn -> + Logger.info("hello", id: 123) + 2 + 2 + end) + + assert log == "id=123 | olleh" + end + end + defp wait_capture_removal() do if ExUnit.CaptureServer in Enum.map(:logger.get_handler_config(), & &1.id) do Process.sleep(20) From c41719be88fb3e6d7dfb0db7a8c12838887a4f4f Mon Sep 17 00:00:00 2001 From: Austin Ziegler Date: Sun, 16 Nov 2025 13:55:18 -0500 Subject: [PATCH 2/2] Update Changelog for ExUnit.CaptureLog Also simplify test --- CHANGELOG.md | 4 + lib/ex_unit/test/ex_unit/capture_log_test.exs | 106 ++++-------------- 2 files changed, 23 insertions(+), 87 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 848d3fcbb05..34f9504f316 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -46,6 +46,10 @@ The type system was made possible thanks to a partnership between [CNRS](https:/ * [Kernel] Warn on unused requires * [Regex] Add `Regex.import/1` to import regexes defined with `/E` +#### ExUnit + + * [ExUnit.CaptureLog] Add `:formatter` option for custom log formatting + #### Mix * [mix test] Add `mix test --dry-run` diff --git a/lib/ex_unit/test/ex_unit/capture_log_test.exs b/lib/ex_unit/test/ex_unit/capture_log_test.exs index 7a7352ac3a2..6de5216899d 100644 --- a/lib/ex_unit/test/ex_unit/capture_log_test.exs +++ b/lib/ex_unit/test/ex_unit/capture_log_test.exs @@ -143,110 +143,42 @@ defmodule ExUnit.CaptureLogTest do end end - defmodule ReverseFormatter do - def new(options \\ []) do - {_, opts} = Logger.Formatter.new(options) + defmodule CustomFormatter do + def new do + {_, opts} = + Logger.Formatter.new( + format: "$metadata| $message", + metadata: [:id], + colors: [enabled: false] + ) + {__MODULE__, opts} end def format(event, config) do event - |> reverse() + |> wrap() |> Logger.Formatter.format(config) end - defp reverse(event) do + defp wrap(event) do msg = event |> Logger.Formatter.format_event(:infinity) |> to_string() - |> String.reverse() - %{event | msg: {:string, msg}} + %{event | msg: {:string, ["[CUSTOM]", msg, "[/CUSTOM]"]}} end end - describe "with formatter" do - test "log tracking" do - logged = - capture_log([formatter: ReverseFormatter.new()], fn -> - Logger.info("one") - - logged = capture_log([formatter: ReverseFormatter.new()], fn -> Logger.error("one") end) - send(test = self(), {:nested, logged}) - - Logger.warning("two") - - spawn(fn -> - Logger.debug("three") - send(test, :done) - end) - - receive do: (:done -> :ok) - end) - - assert logged - assert logged =~ "[info] eno" - assert logged =~ "[warning] owt" - assert logged =~ "[debug] eerht" - assert logged =~ "[error] eno" - - receive do - {:nested, logged} -> - assert logged =~ "[error] eno" - refute logged =~ "[warning] owt" - end - end - - test "with_log/2: returns the result and the log" do - {result, log} = - with_log([formatter: ReverseFormatter.new()], fn -> - Logger.error("calculating...") - 2 + 2 - end) - - assert result == 4 - assert log =~ "...gnitaluclac" - end - - test "respects the :format, :metadata, and :colors options" do - options = [ - formatter: - ReverseFormatter.new( - format: "$metadata| $message", - metadata: [:id], - colors: [enabled: false] - ) - ] - - assert {4, log} = - with_log(options, fn -> - Logger.info("hello", id: 123) - 2 + 2 - end) - - assert log == "id=123 | olleh" - end - - @tag capture_log: true - test "with_log/2: respect options with capture_log: true" do - {_, opts} = - Logger.Formatter.new( - format: "$metadata| $message", - metadata: [:id], - colors: [enabled: false] - ) - - options = [formatter: {ReverseFormatter, opts}] - - assert {4, log} = - with_log(options, fn -> - Logger.info("hello", id: 123) - 2 + 2 - end) + test "uses the formatter from the `:formatter` option" do + log = + capture_log([formatter: CustomFormatter.new()], fn -> + Logger.info("hello", id: 123) + 2 + 2 + end) - assert log == "id=123 | olleh" - end + assert log == "id=123 | [CUSTOM]hello[/CUSTOM]" end defp wait_capture_removal() do