Pytest 3.3: root logger has wrong logging level

[noahl]

In Pytest 3.3, the following test case fails:

    def test_default_level(self):
        self.assertEqual(logging.getLogger().getEffectiveLevel(),
                         logging.WARNING)

It passes in Pytest 3.2. The Python documentation (https://docs.python.org/3.6/library/logging.html#logging.Logger.setLevel) says that the root logger is created with level WARNING, so I believe this is a bug in pytest.

I think this is likely related to #2974 .

[nicoddemus]

Thanks @noahl

[segevfiner]

The cause I think is _pytest/logging.py:289:290. You are calling catching_logs without a level argument which defaults to logging.NOTSET. Meaning that the root logger is set to level logging.NOTSET.

What should the log level for the root logger be? Should it be --log-level?

[nicoddemus]

Meaning that the root logger is set to level logging.NOTSET.

Hmmm feels clumsy at first sight, I would expect it to not change the log level at all if not passed explicitly (but I have little experience with logging myself).

What should the log level for the root logger be? Should it be --log-level?

Again I'm not expert, but that seems reasonable.

[goodboy]

@nicoddemus I ran into this problem as well.

It seems when the logging capture stuff was added somehow the level got set set too low by default - in this case NOTSET is 0 (aka as low as it gets).

I was seeing debug level logs in stress tests which would cause CI to bail due to memory usage.
I had to disable the plugin outright.

[segevfiner]

Summarizing from #3027. The way—I think—logging works when you write a message to a Logger:

1. The Logger finds it's effective log level. If the logger's own log level is NOTSET, it goes upwards in the logger hierarchy looking for the closest logger that has a level that is different than NOTSET.
2. If the message's level is lower than the effective log level it doesn't get passed to any handler at all.
3. If the message is not dropped by the Logger's filtering, than each handler is called. Each handler has it's own log level, which allows the handler to also filter messages by level after the loggers filtering. Note that handlers will be called up the logger hierarchy if the logger's propogate field is True.
   (And this is ignoring some other nasty mechanisms such as log disabling and log filters and who knows what else...)

The log capture module adds a log handler (LogCaptureHandler) to the root logger and this is why—I assume—the logging capture module sets the root logger's log level to NOTSET, since otherwise the messages won't reach it's handler.

To be able to catch all log messages without this would probably require some really nastyclever hacks, unless I'm missing something.

[Sup3rGeo]

Hi guys,

I believe this is related. For some reason I am just getting all logging levels (DEBUG onwards), and the --log-cli-level option has no effect at all on this.

I added some prints inside my test functions and I am always getting level NOTSET for the root logger.

[goodboy]

@Sup3rGeo see discussion in #3013.

[noahl]

@segevfiner your explanation makes sense, but if what you're saying is true, then I think the root logger should default to level WARNING. If it doesn't default to exactly the same level as in a standard Python environment, then any test that tries to check what messages will be generated at runtime will be incorrect. I also found that the documentation (https://docs.pytest.org/en/latest/logging.html , section "Live Logs") says that Pytest will output log records at level WARNING or higher by default, which suggests that the root logger should be at level WARNING.

[nicoddemus]

This will be fixed by #3124.

[nicoddemus]

Btw @noahl. if you can try the #3124 branch it would be great.

[ceridwen]

Is there any chance we can get the fix that prevents pytest from resetting the root logger's level backported to 3.3? At the moment pytest 3.3 is completely unusable because the libraries I depend have such verbose logging, and I have no way to filter it with pytest resetting the root logger for every test.

[nicoddemus]

Is there any chance we can get the fix that prevents pytest from resetting the root logger's level backported to 3.3?

Because this changes the defaults we can't include that in a bug-fix release, I'm afraid; but fear not, I plan to release 3.4 soon, probably next week.

[ceridwen]

Thanks for the prompt response :).

[nicoddemus]

Sure! 👍