Hey all,
I am testing a GenServer that produces a log depending on the result of a message production func via :brod.

Here is the start of the invocation in the GenServer:

  @spec produce_refresh_message(pid :: pid(), RefreshData.t()) :: :ok
  def produce_refresh_message(pid, refresh_data) do
    GenServer.cast(pid, {:produce_refresh_message, refresh_data})
  end

  @impl true
  @spec handle_cast({:produce_refresh_message, RefreshData.t()}, any()) ::
          {:noreply, any()}
  def handle_cast({:produce_refresh_message, refresh_data}, state) do
    refresh_data
    |> format_message()
    |> do_produce_refresh_message()

    {:noreply, state}
  end

Here’s what the func in question looks like:

  def do_produce_refresh_message(message) do
    case kafka_module().produce_sync(:refresh_message_producer, message) do
      :ok ->
        Metrics.kafka_refresh_message_produced(:success)
        :ok
      {:error, reason} ->
        IO.puts "We're in the error block of do_produce_refresh_message"
        Logger.error(%{message: "Failed to produce refresh message", reason: inspect(reason)})
        Metrics.kafka_refresh_message_produced(:error)
        :ok
    end
  end

I am running a test via ExUnit that verifies that the log message is produced in the error case, but… the log is not being emitted, or at the very least, not being captured by the test process.

Here is the test:

    test "it logs a message when the message production fails",
      %{produce_failure_refresh_data: produce_failure_refresh_data, producer_pid: producer_pid} do
      log_output =
        capture_log(fn ->
          # this only works when the function is called directly from the module.
          # if we call the produce_refresh_message function, we get to the Logger line in the module
          # but the Logger.error call does not get captured by the capture_log function for some reason...
          RefreshMessageProducer.produce_refresh_message(producer_pid, produce_failure_refresh_data)

          # for some reason, the direct handle_cast does produce logs correctly...
          # RefreshMessageProducer.handle_cast({:produce_refresh_message, produce_failure_refresh_data}, nil)

        end)

      assert log_output =~ ~s(\"level\":\"error\")
      assert log_output =~ "you blew it, brod."
    end

As you can see in the comments, when the code path is reached via direct invocation of the handle_cast callback, the Log is captured and the test succeeds… but when we call top level function, it does not.

This confuses me greatly. Clearly we’re hitting the Logger codepath in either case, but why would the direct cast ensure that Logger is picked up by ExUnit?

Some context and things I have tried:
The Kafka module is mocked, and we can verify that the error case in the func is being handled because we can see the associated console logs from IO.puts. So at the very least, we know the correct codepath is being executed.

The Metric emission that occurs below the error log also fires, so we are getting past the Logger call.

To invoke the process, we are using the pid of the GenServer which we grab via start_supervised! in the test setup:
producer_pid = start_supervised!(OurModuleUnderTest)

This thread refers to the Logger level filtering that might impact visibility; this can’t be the issue if we can get the same Logger.error through via a direct handle_cast though? Settings in config and test.exs also check out.

So, yeah. Seems like the Logger.error is being sent somewhere, but not to the test process in the one case. I’ve been banging my head on this for a bit, so any thoughts are welcome!