:logger.add_handler/3 sets an unexpected config map

I’ve been trying to add a custom logger backend to my application using the now-recommended :logger.add_handler/3 function as suggested to me by @LostKobrakai (on Twitter). I’ve ran into an issue with the config of the handler, which changes between adding the handler and logging the first event. This is my logger:

defmodule Demo.FileLogger do
  def adding_handler(config) do
    IO.inspect(config, label: "Initial")
    {:ok, config}
  end

  def log(event, config) do
    IO.inspect(event, label: "Event")
    IO.inspect(config, label: "Config")

    :ok
  end
end

This is how I add the handler to my application:

# lib/demo/application.ex
  @impl true
  def start(_type, _args) do
    :ok = :logger.add_handler(:file_log, Demo.FileLogger, %{})
    # ...
end

Now, the handler logs the following config in the adding_handler/1 callback:

Initial: %{
  id: :file_log,
  module: Demo.FileLogger,
  level: :all,
  filters: [],
  filter_default: :log,
  formatter: {:logger_formatter, %{}}
}

but once the log/2 callback is executed for the first time, config only contains the following values:

Config: %{
  id: :file_log,
  module: Demo.FileLogger,
  formatter: {:logger_formatter, %{}}
}

Note the missing level, filters, and filter_default fields. This is surprising to me, because in the “old” :gen_event behaviour for logger backends, you’d set a config during the init/1 callback and this config would be passed to every callback thereafter, just like in a GenServer. Why is this different in the :logger backend and what’s the suggested solution to pass on a config map between all callbacks?

I also implemented the changing_config/2 callback to see whether the config is changed somehow, but it never executes between the adding_handler/1 and the log/2 callback.

Doesn’t the config go under a config key?

%{
  config: %{ level: :error, ...}
}

Yes, I think you’re right. At least that’s what worked for me now. It says so in the docs, too:

Handler specific configuration data is inserted by the handler callback itself, in a sub structure associated with the field named config.

From: logger_handler — kernel v10.0.1

However it’s still confusing because e.g. the spec for the config-type contains all these fields and is references both in the adding_handler/1 and log/2 callbacks, but it’s not the same map in these cases. But anyways. Handler-specific configurations should go under the config.config (also a great naming :D) key I presume.

I found it pretty confusing when I moved to the new erlang logger setup. I think the docs need some love in this area.

1 Like

Yeah, I’m currently battling with converting the old Logger.Formatter.format/5 to :logger_formatter.format/2. Especially converting the old format strings like "$date $time [$level] $message to the new form [:date, " ", :time, " [", :level, "] ", :msg, "\n"] is non-trivial. I appreciate the effort of consolidating the two logging interfaces, but when it comes to extensibility, I’m afraid this is a step backwards.

1 Like

I managed to write a little helper function that’d convert the old format string to the new template-option format: run-elixir/assets/archived_code/file_logger.ex at 85dd2599d9185c259c03f1226912b48e62e73e8c · PJUllrich/run-elixir · GitHub

2 Likes