Can you use ex_unit to assert that a log statement was emitted with specific metadata?

Questions / Help
,
1

I often use ExUnit.CaptureLog to capture information about a log message. But it doesn’t give you any information about the logged metadata. I’ve been adding structured logging recently and I’d like to assert that my code is correctly emitting the correct structured logs, but ExUnit.CaptureLog doesn’t keep or return the metadata. How have others solved this? Maybe we could create a PR to ex_unit that would add a function that returns the metadata along with the captured message?

1 Like
2

At first glance, seems like the tricky part would be getting the results back to what’s calling capture_log - the current code uses a StringIO after formatting the event:

3

Hi, Jason :wave: !

In one project I format logs in json and include metadata there in the message, so it’s pretty straight forward… (Jason.decode the captured log and assert on internals).

However, I guess that’s not your case, so I think we could add :logger handler and try to assert on the metadata within log_event.
Since handlers run in the same process as the one that emits the log we could send the log_event to self() and receive in test roughly something like this:

defmodule LoggerTestHelper do
  def log(log_event, config) do
    send(config.test_pid, {:logged_event, log_event})
  end
end

defmodule Test do
  use ExUnit.Case, async: true
  require Logger

  setup do
    :logger.add_handler(:test_handler, LoggerTestHelper, %{test_pid: self()})
    on_exit(fn -> :logger.remove_handler(:test_handler) end)
  end

  test "metadata" do
    Logger.info("hello", foo: :bar)

    assert_receive {:logged_event, %{meta: meta} = _log_event}
    assert meta.foo == :bar
  end
end

UPD: I just realized, that event might be logged by a process other than the test itself, and sending log_event to self() is quite limiting… Hence, I updated the example passing test_pid to logger handler config and having it to send log_event to test_pid explicitly.

3 Likes
4

Hi Rudolf! :wave:

Oooh, I didn’t expect adding a handler within the test to end up that straightforward and clean! I’ve marked your answer as the solution because it does indeed solve the problem, thank you!

I’ve also extended your example helper slightly to improve the ergonomics, mainly so that it’s easy to get all the logged messages that match a given string, and to return a formatted version of the string (although I’m sure that there’s other cases that would be needed besides {:string, iolist} if this were to hit production:

defmodule LoggerTestHelper do
  def log(log_event, config) do
    message =
      case log_event.msg do
        {:string, iolist} -> to_string(iolist)
      end

    send(config.test_pid, {:logged_event, message, log_event})
  end

  def logs_containing_string(search_string) do
    {:messages, all_messages} = :erlang.process_info(self(), :messages)

    for {:logged_event, message, log_event} <- all_messages,
        String.contains?(message, search_string) do
      {message, log_event}
    end
  end
end

And here’s my example test:

test "logs with metadata", %{conn: conn} do
  {_result, _log} =
    ExUnit.CaptureLog.with_log(fn ->
      conn = get(conn, ~p"/posts")
      assert html_response(conn, 200) =~ "Listing Posts"
    end)

  assert [{message, log}] =
           LoggerTestHelper.logs_containing_string("Sent 200 for GET /posts")

  assert message =~ "2 queries executed in"
  assert message =~ "2 logs captured"

  assert log.meta.method == "GET"
  assert log.meta.request_path == "/posts"
  assert log.meta.duration
  assert log.meta.total_queries == 2

  for query <- log.meta.ecto_queries do
    assert query =~ "FROM \"posts\""
  end
end

If you’re curious about the content of the test I’ve been playing with the ideas of Wide Logs (or Canonical Logs) that are captured quite well in this Stripe blog post:

3 Likes