Can't configure logger in ExUnit tests run with Mix, in Elixir 1.11

Questions / Help
,
1

Hello,

I’m adding support for Elixir 1.11 to a package I maintain and I’m having some issues with the logger configuration. This might be related to this forum thread or issue 6016 on the Elixir GitHub repo.

Until Elixir 1.10, I’ve been able to set the log level in config/test.exs with:

config :logger, level: :error

Now, with Elixir 1.11 this seems to not have any effect and my test output is full of debug lines, e.g. from Ecto.

That line still works in dev (e.g. if I set it in config/config.exs and then run iex -S mix). I’ve also tried with both the old use Mix.Config and the new import Config, with the same results. (For the avoidance of doubt: yes, the test config file is being imported.)

I find it interesting that by the time test/test_helper.exs is executed, I can verify that this configuration has been set:

Logger.level() # :debug
:logger.get_primary_config()[:level] # :debug
Application.get_env(:logger, :level) # :error

Which makes me think that something is preventing Elixir from configuring the Erlang logger in the tests. In dev, the integration works normally and those values appear to be in sync.

The only way I’ve found to make it work is to configure the logger directly in config/test.exs:

- config :logger, level: :error
+ Logger.configure(level: :error)

This feels wrong though, and I can’t help but wonder if there is something obvious that I’ve missed, and an easier way to solve the problem. This kind of change in behaviour between 1.10 and 1.11 seems the kind of thing that someone else must have stumbled upon before.

1 Like
2

Do you start your application for the tests and has it declared its dependency on :logger correctly by adding it to :extra_applications?

Please try to add Application.ensure_all_started(:logger) in test/test_helper.exs before checking the config.

3

Hi @NobbZ, thank you for the pointers. I’ll answer your questions and then add more details.

Do you start your application for the tests

No and yes.
I have a test matrix (1) and some of the test configurations are run with mix test --no-start (...) (2) because in some cases I need granular control over how the applications are started.
To compensate for that, I start my application manually in test_helper.exs, with Application.ensure_all_started(:fun_with_flags) (3).

and has it declared its dependency on :logger correctly by adding it to :extra_applications ?

Yes. (4)

Please try to add Application.ensure_all_started(:logger) in test/test_helper.exs before checking the config.

I’ve done so just in case, but it had no effect. The :logger application was already started anyway (see below), and the the log-level of the Logger is still ignoring what I’m setting in my config files.

More details on what I can see by the time test/test_helper.exs is loaded, which is the same with or without the suggestion from above:

FunWithFlags.Mixfile.application()[:extra_applications]
# [:phoenix_pubsub, :logger, :ecto, :ecto_sql, :postgrex]

Application.loaded_applications()
|> Enum.find(fn(t) -> elem(t, 0) == :logger end)
# {:logger, 'logger', '1.11.2'}

Application.spec(:fun_with_flags, :applications)
# [:kernel, :stdlib, :elixir, :phoenix_pubsub, :logger, :ecto, :ecto_sql, :postgrex, :mock]
4

I’ve verified that the problem is the --no-start flag to mix test. If I run the tests without it, the logger is configured correctly to the :error severity level.

Apparently Application.ensure_all_started(:fun_with_flags) alone is not enough to compensate for the --no-start flag.

1 Like
5

Hey,

I was having the same issue in my project. I rely on mix test --no-start because of my dependency on local-cluster; in my case, I got the previous quiet output in my tests by configuring the Logger module at runtime in test_helpers.exs, adding a Logger.configure([level: :warning]) call.

6

Thanks for confirming that Logger.configure(level: :warning) works.

That worked for me too, but in the end I changed my test setup to not rely on --no-start. (Actually, it turns out that since I adopted that flag something else has changed and now it’s not required anymore. I need to investigate that more.)

It still seems odd that this would change between Elixir 1.10 and 1.11.

7

I’m having a similar issue where I have the log level configured in config/test.exs (which is imported properly) and the above are the same. The app env is getting set but it’s not getting to the Erlang logger, even though I have Application.ensure_all_started(:logger) in my test_helper.exs.

It must be the --no-start issue but I’m not sure how to fix it properly because only Logger.configure(level: :warning) works :confused:

8

For future reference for devs having this issue with --no-start:

This issue occurs when running mix test --no-start and causes the application tree to not start.
The usual advice when runnning with --no-start is to use Application.ensure_all_started/2 to start the application tree under your test_helper.exs, however this is not ideal as the :logger application would have been started prior to calling this, resulting in your config.exs not being respected.
This can be seen in the following code in the mix app.start task, which mix test delegates application starting to. In the linked snippet,the Logger application is actually killed when the application is started on the test run.

As such, it would be necessary to use the app.start task directly instead of using Application.ensure_all_started/2 so that the :logger module works correctly and as expected.

Hence, your test_helper.exs should be updated to:

Mix.Task.run("app.start")
ExUnit.start()
2 Likes