pytest log init timing changed; now code-under-test with logging.basicConfig fails

[dmick]

Discovered kinda by accident [1]: pytest logging code now initializes handlers on the root logger before the application-under-test code has a chance to configure logging, which causes the usual "easy" logging initialization by the code-under-test with logging.basicConfig() to be ignored (basicConfig exits if there are any handlers already installed on root logger). This changed somewhere between pytest 3.7.1 and 6.2.5.

One can imagine application code that relies on the logging configuration to continue working even during test (logging to a private file, or a log server, etc.), so this seems like a possibly-wider-breaking change than our particular situation [1].

What do you think? Should pytest try to delay logging initialization until it's imported the modules under test, so that their possible (perhaps likely) calls to logging.basicConfig are not neutered?

[1] Normally this wouldn't be that big a deal, as there is a root logger configured, so log messages are captured by pytest and there are a million ways to see them (although "seeing them" may not be the only intent of the application's logging configuration choices). The unexpected side effect that brought this to my notice is that logging.LogRecord doesn't contain an asctime field as a result, because, despite being documented as one of the attributes of LogRecord, it's only populated if one of the Formatters contains a string with a reference to 'asctime' (and the LogRecord passes through format()). (I suspect this is both because it's expensive to generate if not needed and a consequence of the logging module's Formatter containing info about how to format date/time, but it's surprised others before about logging.LogRecord.asctime.) It turned out we had a test that referred to that field from caplog.records, and that test started failing with "attribute not found" when we updated pytest.

[nicoddemus]

Perhaps @Thisch @RonnyPfannschmidt could chime in? I don't really use logging so I can't weight in on this.

[dmick]

Does anyone have any comment on this? I didn't want to start with a bug/issue because I wanted to get a feel for whether my surprise is warranted.

[dmick]

@Thisch @RonnyPfannschmidt do you have any comments?

[twmr]

To avoid this I never run logging.basicConfig or other logging code that changes the root logger in the code started by pytest.
I know that we already had several discussions about whether pytest should support testing code that changes the root logger or not. I remember a very good answer from @RonnyPfannschmidt, which I'll try to find.

[twmr]

This is the comment that I meant:
#5502 (comment)