When/how is Logger app started?

Questions / Help
,
1

I have a legacy Erlang app that is part of Mix umbrella project. The app has eunit tests that are ran using a custom Mix task. When migrating the whole project to Erlang/OTP 23 and Elixir 1.11 I switched logging from lager to Erlang logger (with Elixir backend) and for some reason logger config is not loaded from test.exs when running this custom eunit mix task - logger gets some default configuration with level: :all which is not ideal :slight_smile: .

This is not really specific to this mix task, this is true for any mix task it seems. Maybe the logger app is started before the config is loaded?

For example:

defmodule Mix.Tasks.Hello do
  use Mix.Task
  require Logger

  def run(_) do
    IO.inspect(Application.get_all_env(:logger))
    # level is info:

    # [
    #   utc_log: false,
    #   translators: [{Logger.Translator, :translate}],
    #   backends: [:console],
    #   discard_threshold_for_error_logger: 500,
    #   handle_sasl_reports: false,
    #   truncate: 8096,
    #   discard_threshold: 500,
    #   compile_time_application: nil,
    #   sync_threshold: 20,
    #   discard_threshold_periodic_check: 30000,
    #   console: [level: :info, format: {LoggerFormatter, :format}, metadata: :all],
    #   handle_otp_reports: true,
    #   start_options: [],
    #   level: :info,
    #   translator_inspect_opts: [],
    #   compile_time_purge_matching: []
    # ]

    Logger.debug("!!!")
    # level is info in config but still a debug message is printed
    # !!!

    IO.inspect(:logger.get_config())
    # level: :all is set for Elixir handler

    # %{
    #   handlers: [
    #     %{
    #       config: %{ ... },
    #       filter_default: :stop,
    #       filters: [
    #         filter_non_ssl: {&:logger_filters.domain/2, {:log, :sub, [:otp, :ssl]}}
    #       ],
    #       formatter: {:ssl_logger, %{}},
    #       id: :ssl_handler,
    #       level: :debug,
    #       module: :logger_std_h
    #     },
    #     %{
    #       config: %{ ... },
    #       filter_default: :log,
    #       filters: [],
    #       formatter: {:logger_formatter, %{}},
    #       id: Logger,
    #       level: :all,
    #       module: Logger.Handler
    #     }
    #   ],
    #   module_levels: [ssl_logger: :debug],
    #   primary: %{
    #     filter_default: :log,
    #     filters: [process_disabled: {&Logger.Filter.process_disabled/2, []}],
    #     level: :debug
    #   },
    #   proxy: %{ ... }
    # }
  end
end

How and when is the Logger app started when Mix task is ran? Why is the specified env config not loaded?
Thanks!

2

Apparently I misunderstood how logger configuration works.
When running iex -S mix in dev env with logger level set to info in config, none of the logger handlers have info level set:

:logger.get_config()
%{
  handlers: [
    %{
      config: %{
        sasl: false,
        thresholds: {20, 500},
        translators: [{Logger.Translator, :translate}],
        truncate: 8096,
        utc_log: false
      },
      filter_default: :log,
      filters: [],
      formatter: {:logger_formatter, %{}},
      id: Logger,
      level: :all,
      module: Logger.Handler
    },
    %{
      config: %{
        burst_limit_enable: true,
        burst_limit_max_count: 500,
        burst_limit_window_time: 1000,
        drop_mode_qlen: 200,
        filesync_repeat_interval: :no_repeat,
        flush_qlen: 1000,
        overload_kill_enable: false,
        overload_kill_mem_size: 3000000,
        overload_kill_qlen: 20000,
        overload_kill_restart_after: 5000,
        sync_mode_qlen: 10,
        type: :standard_io
      },
      filter_default: :stop,
      filters: [
        filter_non_ssl: {&:logger_filters.domain/2, {:log, :sub, [:otp, :ssl]}}
      ],
      formatter: {:ssl_logger, %{}},
      id: :ssl_handler,
      level: :debug,
      module: :logger_std_h
    }
  ],
  module_levels: [ssl_logger: :debug],
  primary: %{
    filter_default: :log,
    filters: [
      process_disabled: {&Logger.Filter.process_disabled/2, []},
      silence_logger_exit: {&Logger.Filter.silence_logger_exit/2, []}
    ],
    level: :debug
  },
  proxy: %{
    burst_limit_enable: false,
    burst_limit_max_count: 500,
    burst_limit_window_time: 1000,
    drop_mode_qlen: 1000,
    flush_qlen: 5000,
    overload_kill_enable: false,
    overload_kill_mem_size: 3000000,
    overload_kill_qlen: 20000,
    overload_kill_restart_after: 5000,
    sync_mode_qlen: 500
  }
}

but debug messages are not printed somehow (filtered in Elixir logger process?). Does this mean when logging is done from Erlang code (i.e. ?LOG_INFO(...)) all logging messages will be sent to the handler process regardless of the the current logging level (and not filtered in the caller process?)?

3

:logger and Logger are separate beasts. :logger is part of Erlang’s :kernel application and cannot be directly configured via config.exs file (as it is already loaded and started when config.exs is parsed) and :logger application is part of Elixir’s distribution. From now I will call them :logger module and logger application respectively.

The current flow is as follows (simplified):

  • kernel application is started (so :logger module is configured)
  • config.exs file is loaded (so it cannot configure :logger module)
  • logger application is started
  • logger application configures :logger module to use Elixir’s configuration

So if you want to change log level from the config.exs then you need to use logger application:

config :logger, level: :warning

This should set :logger.get_config().primary.level to :warning so messages would be filtered by :logger module.

Yes, this is a little bit confusing, because of the compatibility reasons in Elixir, but I hope to improve that over a time in the future.

3 Likes
4

Thanks for the explanation!

Yes, I do understand that Erlang :logger and Elixir Logger app are not the same.

In the Logger documentation it is stated that

we do not recommend configuring Erlang/OTP's logger directly under the :kernel application in your config/config.exs

So I can’t configure :logger using config in .exs file directly. Ok, but I expected that Erlang :logger is configured by Logger when the Logger app starts, and judging from the :logger.get_config() output Logger did install itself as a handler. But the Erlang’s :logger handlers levels were not set to one configured in .exs config file (none of them have :info level, Logger handler level is :all) - is it the intended behavior?

Erlang :logger docs state that when logger macros are used (like ?LOG_DEBUG(...)), the level is checked in the caller process and if for example the level is set to info, ?LOG_DEBUG(...) will not result in sending message to the logger process. But it seems that in this case the :logger level is not set to :info even if I have config :logger, level: :info set in config. So it seems that calling ?LOG_DEBUG(...) from Erlang app will actually result in sending a message to the handler anyway, is this correct?

So if you want to change log level from the config.exs then you need to use logger application:

config :logger, level: :warning

that’s the problem from the first post, I have config :logger, level: :info set in config and Application.get_all_env(:logger) shows that the level is indeed set to :info, but Logger.debug(...) output is printed anyway.

5

Just to confirm - what is the Elixir version you are on? It could help finding the possible reason, because it seems like bug in Logger. You can create issue on GitHub and ping me there.

6

Elixir 1.11.2, Erlang 23.2.

You can create issue on GitHub and ping me there.

Are you talking about Erlang’s logger handlers’ levels or getting a debug output when the Elixir Logger level is set to info in config?
I’m just not sure if the latter is not some misconfig on my part :slight_smile: Are you able to reproduce this?