caplog fixture should not be affected by global log level

[nicoddemus]

#7159 made me realize something: I think caplog by default should not be affected by the global log level.

For example:

import logging

def test(caplog):
    logging.info("info")
    logging.critical("critical")
    print(caplog.messages)
    assert 0

Running:

 λ pytest .tmp\test-caplevel.py
======================== test session starts ========================
collected 1 item

.tmp\test-caplevel.py F                                        [100%]

============================= FAILURES ==============================
_______________________________ test ________________________________

caplog = <_pytest.logging.LogCaptureFixture object at 0x000001827FB75358>

    def test(caplog):
        logging.info("info")
        logging.critical("critical")
        logging.debug("debug")
        print(caplog.messages)
>       assert 0
E       assert 0

.tmp\test-caplevel.py:8: AssertionError
----------------------- Captured stdout call ------------------------
['critical']
------------------------- Captured log call -------------------------
CRITICAL root:test-caplevel.py:5 critical
========================= 1 failed in 0.25s =========================

λ pytest .tmp\test-caplevel.py -o log_level=INFO
======================== test session starts ========================
platform win32 -- Python 3.6.6, pytest-5.4.1.dev154+gbe6849644.d20200501, py-1.8.1, pluggy-0.13.0
hypothesis profile 'default' -> database=DirectoryBasedExampleDatabase('d:\\projects\\pytest\\.hypothesis\\examples')
rootdir: d:\projects\pytest\.tmp, inifile: pytest.ini
plugins: hypothesis-4.36.0, forked-1.1.1, xdist-1.31.0
collected 1 item

.tmp\test-caplevel.py F                                        [100%]

============================= FAILURES ==============================
_______________________________ test ________________________________

caplog = <_pytest.logging.LogCaptureFixture object at 0x0000014A1CCD32E8>

    def test(caplog):
        logging.info("info")
        logging.critical("critical")
        logging.debug("debug")
        print(caplog.messages)
>       assert 0
E       assert 0

.tmp\test-caplevel.py:8: AssertionError
----------------------- Captured stdout call ------------------------
['info', 'critical']
------------------------- Captured log call -------------------------
INFO     root:test-caplevel.py:4 info
CRITICAL root:test-caplevel.py:5 critical
====================== short test summary info ======================
FAILED .tmp\test-caplevel.py::test - assert 0
========================= 1 failed in 0.24s =========================

So depending of the loglevel setting, the test might fail. #7159 is a step in the right direction, because calling caplog.set_level will overwrite the global log level.

But I think this is kind of error prone too, and caplog should have a default log-level value (say INFO), independent from the global log level, which is changed only by calling set_level explicitly.

cc @Thisch @ruaridhw

[ruaridhw]

Currently, I believe that the default log-level just happens to be WARNING since this is the default of the root logger. In your example, if we change the default to be INFO, I'm not sure how this fixes the issue because won't users just come to rely on a default of INFO rather than WARNING? Given that the root logger default is WARNING, who's to say that the caplog default should be different to that?

So depending of the loglevel setting, the test might fail.

This was the premise behind raising #7133. I believe the test should have the final say as to the log level it requires. Therefore I don't see any solution to your example other than the test setting at_level() or with_level() itself during the run since it should be responsible for knowing the loglevel it is asserting against. That way, no matter the CLI option passed in, the test will always pass since these options will only influence Captured log call with #7159

[twmr]

I agree that the caplog should not be affected by the global log level, but I also think that log level used for the reports should not be affected by the caplog (both are fixed by #7159)

[nicoddemus]

Therefore I don't see any solution to your example other than the test setting at_level() or with_level() itself during the run since it should be responsible for knowing the loglevel it is asserting against

I think we are in agreement, I might not have expressed myself well enough: I think caplog should always have a default log-level set (WARNING seems to be more sensible than INFO), same as if at the beginning of the test the user has set caplog.set_level. Of course if the user needs another log-level for caplog, it may override this in the test.

My point is that it is easy for a user to write a test that passes without setting caplog.log_level explicitly, which will then fail when someone changes the global log level in the command-line, so caplog should have a log-level set by default always, independent from the global log-level.

I agree that the caplog should not be affected by the global log level, but I also think that log level used for the reports should not be affected by the caplog

I agree with all your points here, just to be clear though, #7159 does not take care of the change I'm proposing here (the output we see above is the same with #7159).

[ruaridhw]

which will then fail when someone changes the global log level in the command-line

I would view this as a fault of the test. I would expect that if the test asserts on a logging message it needs to set caplog.log_level explicitly within the test code. That's just my opinion though! So in your example, if you require caplog to capture below WARNING, it should explicitly state this.

Irrespective of that, to me this "default log-level" for caplog is the --log_level option that is determined at runtime. Currently, users are allowed to rely on this option (or the ini file) to configure caplog's level:

import logging

def test(caplog):
    logging.debug("debug")
    assert 'debug' in caplog.text

[pytest]
log_level=DEBUG

Calling pytest on the above code will pass only because of the ini file. Without it, the test will fail because the default is to ignore DEBUG. I believe if we implement this issue, it will be a breaking change because we're saying the proposed caplog default could be different to the global log level.

Further, if we introduce a new setting for this would the plan be to not expose that to the CLI/ini and only allow it to be configured in the test code? Otherwise we have the same issue again; tests could fail due to a config option.

I don't feel particularly strongly about this though, that was just how I reasoned about the design of #7159. Taking this to the extreme, a runner could exec pytest --log_level=100 and every caplog test would fail presuming their tests don't control caplog's level themselves 😱

[nicoddemus]

I would view this as a fault of the test. I would expect that if the test asserts on a logging message it needs to set caplog.log_level explicitly within the test code. That's just my opinion though! So in your example, if you require caplog to capture below WARNING, it should explicitly state this.

I understand the reasoning, but I think we should have reasonable defaults to avoid having users writing wrong tests by accident; there's nothing preventing a user to write a test without setting caplog.log_level and having the test pass, only to break once someone decides to pass --log-level on the command-line (to see different level of captured logs) and having caplog tests fail because of that.

With caplog.log_level having a default value independent from the global value, the average user will be protected in the common case.

Calling pytest on the above code will pass only because of the ini file. Without it, the test will fail because the default is to ignore DEBUG. I believe if we implement this issue, it will be a breaking change because we're saying the proposed caplog default could be different to the global log level.

Oh you are right, this is a breaking change (forgot to make it explicit), but I believe it is for the best though. It certainly would need to be released in pytest 6.0.0.

Taking this to the extreme, a runner could exec pytest --log_level=100 and every caplog test would fail presuming their tests don't control caplog's level themselves

Yes that's what my proposal tries to avoid. 👍

[ruaridhw]

@nicoddemus, yes that all makes sense to me.

[bluetech]

The way it is currently implemented, caplog doesn't do anything on its own; it reuses the log capturing that is set up for test reporting.

The semantics I propose are:

• caplog is completely independent from log_level.
• caplog only captures while it (the fixture) is active (independent from runtest hooks).
• caplog captures all levels.

Regarding the last point, @nicoddemus said that the default level should be WARNING, but I think it is more expected for it to capture everything, and the user can assert the level and ignore messages they don't want to assert. caplog is used specifically to test log messages, I don't think that if the user wants to test a DEBUG log message, we should require an extra set_level step.

@ruaridhw PR #7159 starts doing this separation but if ⬆️ is what we want, it will require some changes.

@ruaridhw @nicoddemus @Thisch WDYT?

[twmr]

@bluetech so what you are saying is that if a user doesn't want to capture all levels, he/she can call set_level, right? If we can assure that a LogCaptureHandler is only created for tests that use the caplog fixture, I agree with your proposal. Otherwise I would use WARNING as the default log-level for caplog, to avoid potential performance regressions.

[ruaridhw]

I think it is more expected for it to capture everything

Couldn't this lead to pretty significant memory issues? If there are MBs of DEBUG logs being sent to the logger during a function call but the user is only interested in a couple of lines of WARNING messages then there would be performance implications, right?

Given that the root logger level is WARNING by design, I imagine that if one expects to test a DEBUG log message, they may be used to having to manually configure the logger via an extra step anyway.

[bluetech]

My idea of using the fixture scope for the scope of its capturing doesn't work
out. The problem specifically is caplog.get_records('setup') -- it expects to
receive all records from the setup phase, even before the caplog itself
came into scope. This means that caplog needs to use an existing capturing
set up by plugin in the hooks.

---

Regarding the log level:

Currently, the fixture capturing is using the existing test-reporting
capturing. This issue proposes to separate it to a new capturing such that the global log level doesn't affect the fixture.

Assuming we make the fixtures use their own handler, the situation will be this:

• File capturing -- uses log_file_level ini/option, fallback to log_level, default None.
• CLI capturing -- uses log_cli_level ini/option, default None.
• Report capturing -- uses ``log_levelini/option, defaultNone`.
• Fixture capturing -- TBD

Whenever one of the above types of capturing is entered (file and cli --
global, report and fixture -- in each runtest phase), and its level is not
None, it sets the level for its handler and and also lowers the root logger's
level to its level, if it is higher, and restores it when it exits.

If its level is None, the handler's level is not set (=> logging.NOTSET),
and it accepts all log messages that reach it. The root logger's level is also
not set, meaning its level is the one set by caplog.set_level, or one of the
other types, or by the user, or the default WARNING.

In order to make the fixture capturing independent of the other log levels,
we need to set the TBD above to some constant level (e.g. WARNING). But
due to how things work (as explained above), this will affect all of the
others as well. And this wreaks havoc to the tests at least.

This is as far as a I went -- I don't think there's a perfect solution for this :(.