Log Level on "info" despite configured otherwise

Questions / Help
, ,
1

Hello there!

I am currently facing an issue with the logger.
At some point it started logging at info level only despite being configured to log at debug level. The interesting thing is that it used to work fine before. I am not sure what broke it, since I wasn’t working on the project for over a month. So it may have been a breaking Elixir update or a lack of knowledge by making a bad change on my part.

This is my elixir version:

patrick@PATRICK:~$ elixir -v
Erlang/OTP 22 [erts-10.6.1] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [hipe]

Elixir 1.9.4 (compiled with Erlang/OTP 21)

This is my logger configuration:

config :logger,
  level: :debug

config :logger, :console,
  metadata: :all,
  level: :debug,
  format: {Sahnee.Logger, :format}

(The formater is not related to this, removing the custom formater yielded the same result)

If I launch my application with iex -S mix the logger is configured to level info:

iex(2)> require Logger
Logger
iex(3)> Logger.level
:info
iex(4)> Logger.debug("debug")
:ok
iex(5)> Logger.info("info")
:ok
15:49:45-875 [info]  #PID<0.1106.0>@.:5
 info
iex(6)> Logger.configure(level: :debug)
:ok
iex(7)> Logger.debug("debug2")         
:ok
15:49:56-202 [debug] #PID<0.1106.0>@.:7
 debug2

Can anyone point out why this is happening? No calls to Logger.configure are made in the application code.

Thank you for your time!
Patrick

2

Are you using correct MIX_ENV?

3

I am not setting it explictly, just running iex -S mix. Should I be doing this? If so, where and how?

Checking the env tells me that its in dev mode: (which is what I want, I am on my development machine)

iex(3)> Mix.env
:dev
4

In which file is your logger config? And is that file actually loaded from your config.exs.

5

My config is in a file called sys.exs. This file is loaded in the first line of my config.exs. The file also contains several other options (such as the Ecto Repo, etc.) which are working.

use Mix.Config

import_config "sys.exs"

Interestingly enough, all values other than the log level are also loaded:

iex(3)> Application.get_env :logger, :level
:info
iex(4)> Application.get_env :logger, :console
[metadata: :all, level: :debug, format: {Sahnee.Logger, :format}]

There also do not seem to be any other places where this config value is changed:

image

6

What happens if you switch from use Mix.Config to import Config?

7

Same result, all config values except this single one are applied:

iex(1)> Application.get_all_env :logger
[
  utc_log: false,
  translator_inspect_opts: [],
  compile_time_application: nil,
  handle_sasl_reports: false,
  truncate: 8096,
  compile_time_purge_level: :debug,
  level: :info, # <--
  sync_threshold: 20,
  discard_threshold_for_error_logger: 500,
  handle_otp_reports: true,
  discard_threshold: 500,
  console: [metadata: :all, level: :debug, format: {Sahnee.Logger, :format}],
  compile_time_purge_matching: [],
  backends: [:console],
  discard_threshold_periodic_check: 30000,
  translators: [
    {Plug.Cowboy.Translator, :translate},
    {Logger.Translator, :translate}
  ]
]

config.exs:

#use Mix.Config
import Config

import_config "sys.exs"

# snip...

sys.exs:

#use Mix.Config
import Config

# snip...

config :logger,
  level: :debug

config :logger, :console,
  metadata: :all,
  level: :debug,
  format: {Sahnee.Logger, :format}

# snip...
8

What is in # Snip parts? Are you sure that you do not set that key to different value later?

9

Unfortunately not, no. I posted a screenshort earlier where I searched for :logger in my entire project. The term has only three occurences: Two for the two config entries posted above and one in extra_application to actually start the logger (I think, been a while since I set it up).

image

image

image

If you absolutely want to see the full config I can post it, but since its roghly 150 lines I’d prefer to spare you the wall of text. (Also worried about forgetting to remove a production secret :D)

10

Just use paste bin. However it is hard to tell you where the bug can be. Unfortunately logger isn’t external application so it isn’t that simple to edit it.

Try searching for Logger, maybe there is some rouge call that changes it in the application itself.

11
  • config.exs: config.exs - Pastebin.com
  • sys.exs: sys.exs - Pastebin.com
  • local.exs: I cannot post this file under any circumstances since its only purpose is to store secrets that should not be commited to git. (Neither :logger nor Logger are used or configured within this file.)

Try searching for Logger , maybe there is some rouge call that changes it in the application itself.

Which terms would be of interest to search? It’s a large application (by my standards) so there are hundrets of Logger calls. Logger.configure is not called. Asides from normal log statements a lot of metadata is being set, but no metadata entry is called level or contains the value info if that could be a culprit.

Thanks to everyone who has posted so far. This is probably going to be an embarassing “oops” kind of mistake that I made, but the source of it eludes me.

12

Actually I have a similar problem with Logger.

I have a config/test.exs like this

import Config

# Print only warnings and errors during test
config :logger,
  backends: [:console],
  level: :warning

and yet the Logger.info() lines in my app still print out to console in ‘mix test’.
Now I know that this config is actually being read, because when I change it to

config :logger,
  backends: [:console],
  compile_time_purge_matching: [
    [level_lower_than: :warning]
  ]

This actually works in removing the info level log lines.

I have searched the project, and there doesn’t seem to have any calls to Logger.configure/1 that would be setting the level back. Unless it is somehow being set in my dependencies?

Anyhow, don’t want to hijack this thread. Just wanted to know we have a shared issue with Logger acting funny.

13

to be honest, I use only :warning level, because the logger configuration never appear to works.

14

In order for Logger to respect the configuration, :logger application must be started.

Ensure you have this in you mix.exs

  def application do
    [
      extra_applications: [:logger],
      ...
    ]
  end
15

Something else to watch, if you’re using escript: The config/*.exs settings get built into the escript binary when it’s compiled. If you change them, you need to recompile the binary for the change to take effect.