Logger: build log-message as data, postpone actual logging

Questions / Help
,
1

I’m just trying to make the functional core of my application as pure as possible, following the functional core, imperative shell pattern.

One problem I have is logging. Consider this code deep in the core:

case var do
  :foo -> 
     {:ok, "foo"}
  :bar -> 
     {:error, "bar"}
end

So one of the possible return values of the core would be{:error, "bar"}. This error is just data, so I can easily write a test, that’s good. But I would also like to log it. I could:

  • write a handler in the shell that matches on all errors and logs them. But then I’m missing Logger’s metadata.
  • I could prepend each {:error, ...} with a call to Logger

What I’d rather do is sth like this:

  • core: {:error, {"bar", Logger.get_all_meta([custom_meta: :my_metadata])}}
  • shell: use this data to log at one place outside the core with correct metadata
2 Likes
2

I would just slap logging in place. While this mean that there is a little of “impurity” in “core” that doesn’t really matter, as that “impurity” do not affect the overall system. So unless there are other considerations that you do not listed in your post, then I would just do not care about it.

However if you want to have it just in case when you need debugging, then you probably would prefer setup dynamic tracing on that function.

2 Likes
3

I number (correct) logging among the overall system.
But the main point is: I’d like to be able to do it for the sake of purity alone. I know that’s not a good reason, but right now I see it as a sport.

I did not yet look into tracing yet, but I definitely will.

4

By “overall system” I meant core computation of your application.

Just remember that there are 2 “kinds” of tracing. Dynamic that should be used only for debugging (as there can be only one dynamic tracer per module) and “static” one that is meant to be observability tool (see OpenTelemetry).

If it is just experimenting then you are free to go, but for me it seems like over complicating things that are meant to be simple.

1 Like
5

If you just want to test logging, can use CaptureLog:

  test "capture error log" do
    import ExUnit.CaptureLog
    require Logger
    assert capture_log(fn -> Logger.error("?") end) =~ "?"
  end
2 Likes
6

I didn’t know about capture_log, nice.
As it seems Logger supports structured logging (you can log a map) so if capture_log can match on a map (?) the testing-log-messages thing is covered.

@hauleth yes just experimenting. I did OOP and C my whole life. Now seeing how things can be done functionally I kind of want to wash all the impurity away. It’s not rational.

7

The capture_log only works with console backend of logger. And the map log will be formated into string when it goes to IO.

So you can test it by:

  test "capture error log" do
    import ExUnit.CaptureLog
    require Logger
    assert capture_log(fn -> Logger.error(%{key: "value"}) end) =~ "key: \"value\""
  end
8

No, as @Ljzn said it works with already formatted data (however in contrast to what they said, you aren’t forced to use console logger in test to make it work).

If you want to test against structure of the logged message when working with structured logging then you need a little more footwork. I will provide you example how to do so a little bit later as I am on mobile, so if you could please ping me about it in an hour or two.

1 Like
9

Ok, now I can write about it.

To be able to listen to the data for given process, then you need to instantiate your own handler. Simplest approach to that would be:

defmodule CaptureStructuredLogs do
  def capture_log(callback) do
    this = self()
    handler_id = :"handler_#{inspect(this)}"

    :ok = :logger.add_handler(handler_id, __MODULE__, %{config: %{pid: this}})
    try do
      callback.()
    after
      :logger.remove_handler(handler_id)
    end

    fetch_all_messages([])
  end

  defp fetch_all_messages(messages) do
    receive do
      {{__MODULE__, :log}, log_event} ->
        fetch_all_messages([log_event | messages])
    after
      0 -> Enum.reverse(messages)
    end
  end

  def adding_handler(%{config: %{pid: pid}} = config) when is_pid(pid), do: {:ok, config}
  def adding_handler(_), do: {:error, :required_pid}

  def log(log_event, %{config: %{pid: pid}}) do
    send(pid, {{__MODULE__, :log}, log_event)
  end
end

Now you can use it like “old” function:

test "capture log" do
  import CaptureStructuredLogs
  require Logger
  assert [%{msg: {:report, %{key: "value"}}}] = capture_log(fn -> Logger.error(%{key: "value"}) end)
end
4 Likes
10

If I understand correctly, you want to log the file/line where the error is produced? I typically don’t obsess about that, but instead aim to make different branches return different errors, which means that I can deduce the source of the error from its content.

However, if I really wanted to preserve the stack trace I’d probably log in place, as @hauleth said.

But, if you want to stick to pure functional for fun & sport, you could use __ENV__ to include file & line in the returned error, and then include that info in the logged message.

2 Likes
11

That’s cool. With some unpacking in fetch_all_messages:

defp fetch_all_messages(messages) do
  receive do
    {{__MODULE__, :log}, %{level: level, msg: {_, msg}}} ->
      fetch_all_messages([{level, msg} | messages])
...

I can write very clean assertions against the Logger:

assert [info: "this is a info message", error: "this is an error message"] =
          capture_log(fn ->
            Logger.info("this is a info message")
            Logger.error("this is an error message")
          end)

assert [info: %{something: :reported}] =
          capture_log(fn -> Logger.info(%{something: :reported, this: :info}) end)

assert [info: [something: :reported, this: :info]] =
          capture_log(fn -> Logger.info(something: :reported, this: :info) end)

Why is something like this not the default for capture_log? You are explicitly allowed to log maps and keyword lists, why can’t ExUnit match on them (by default). Having this module in the test_helper may be a little intimidating.

@sasajuric I will go for __ENV__ in the core to keep it perfectly immaculate!

12

Because of the backward compatibility. I can check out if that could be “fixed” by adding new module to ExUnit though. I will try to provide PR tomorrow (CET) unless you will do that first. You can ping me in PR if you want.

2 Likes
13

I’m just doing my first steps with Elixir, I can’t possibly create a PR for ExUnit. Most likely it would break all tests in the world.

btw there is a } missing in your code:

def log(log_event, %{config: %{pid: pid}}) do
-  send(pid, {{__MODULE__, :log}, log_event)
+  send(pid, {{__MODULE__, :log}, log_event})
end
1 Like
15

there is a bug in the last version, it can’t handle complex data, this should be better, but most likely is still flawed.

   # with log level :info

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

defmodule PureLogger do
  @levels [:emergency, :alert, :critical, :error, :warning, :notice, :info, :debug]

  for level <- @levels do
    defmacro unquote(level)(data) do
      maybe_log(unquote(level), data, __CALLER__)
    end
  end

  def maybe_log(level, data, caller) do
    meta = Map.take(caller, [:file, :line])

    if do_log?(level) do
      quote do
        [
          {
            :logger,
            unquote(level),
            {
              unquote(data),
              unquote(Macro.escape(meta))
            }
          }
        ]
      end
    else
      []
    end
  end

  defp do_log?(level) do
    min_level = Application.get_env(:toy, :log_min_level, :all)
    :logger.compare_levels(level, min_level) == :gt
  end
end