How to have uncaptured logger calls generate failures in ExUnit?

Questions / Help
,
1

I’d like that any test that generates uncaptured log entries fails.

Is there an easy way to do this?

Otherwise, would adding a custom Logger backend work, i.e. would it not be called if there’s a @capture_log tag or if the test is wrapped in capture_log(...)?

1 Like
2

what is an “uncaptured log entry”?

Do you want to be able to assert that sth was logged in your tests, like:

assert {:logger, :error, "sth went wrong"} = thishouldfail()

?

3

There is no such feature at the moment. It would need to be added to Elixir. But keep in mind that, given your tests run concurrently, this could cause Heisenfailures as one test could incorrectly capture the logs of another test and not fail when it should fail (which is ok, it would not be ok to fail when it should not have).

1 Like
4

Here’s are examples of captured/uncaptured entries:

test "this is captured" do
  assert capture_log(fn ->
    Logger.warn("example")
  end) =~ "example"
end

@tag capture_log
test "this is captured too" do
  Logger.warn("example")
end

test "this is not captured and should fail" do
  Logger.warn("example")
end
1 Like
5

Yeah, we could support a @tag :assert_no_log.

1 Like
6

Right. As long as there are no tests that capture the log are marked as async, things should be ok.

That would be awesome.

I’m browsing the code and it’s not clear to me how to implement this; pointers welcome if you’d like me to prepare a PR.

7

The interaction of this with async: true is definitely troublesome; for instance, the Logger.warn in LogTest2 currently always gets captured and so presumably wouldn’t fail if assert_no_log was hooked up:

defmodule LogTest1 do
  use ExUnit.Case, async: true

  import ExUnit.CaptureLog
  require Logger

  test "this is captured" do
    assert capture_log(fn ->
      Process.sleep(1000)
      Logger.warn("example")
    end) =~ "example"
  end

  @tag :capture_log
  test "this is captured too" do
    Logger.warn("example")
  end
end

defmodule LogTest2 do
  use ExUnit.Case, async: true

  require Logger

  @tag :assert_no_log
  test "this is not captured and should fail" do
    Logger.warn("example")
  end
end

The Process.sleep here represents “real work” happening inside the capture_log block; with a looooong sleep like this the test in LogTest2 always runs while the block in LogTest1 is active.

8

I was in the same situation, that I wanted to include logging in the tests. I ended up writing a little macro that gets some meta-data from __CALLER__ and generates log-tuples

assert [{:logger, :error, {4711, %{file: _, line: _}}}] = error(4711)
assert [{:logger, :warning, {'test', %{file: _, line: _}}}] = warning('test')
assert [{:logger, :debug, {[a: 1, b: 2], %{file: _, line: _}}}] = debug([a: 1, b: 2])

The advantage over capture_log is, that you can use structured logging while capture_log can only use the console backend. Also it’s absolutely pure (if you are strict and see logging as impure) so there are no problems with async. But you have to handle the log-data the core produces somehow in the shell (and do the real logging).

2 Likes
9

This is where we check for capture log tag: elixir/lib/ex_unit/lib/ex_unit/runner.ex at main · elixir-lang/elixir · GitHub

We probably want to make it a tri-state: :capture, :none, :assert. And then fail the test if it passes but has a log in asset mode.

1 Like