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

[dmick]

Discussed in #9324

^{Originally posted by dmick November 19, 2021}
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.

[The-Compiler]

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?

It seems like a code smell to me to configure logging at import time - IMHO, importing a module shouldn't do stuff like that.

Usually I suppose you'd call some kind of init_logging function or whatever, maybe from a fixture. I guess it'd be good if pytest could play nicer with those use-cases, but I don't think delaying it to after the imports will help in common cases.

[dmick]

Not sure what you mean by "code smell" exactly....does that mean "bad idea"? Yeah, perhaps, but it's about as early as any app could do it, and if even import time is too late for pytest, it's an even better reason for delaying pytest's log setup, it seems.

As for "call from a fixture"....is a fixture relevant for non-test code? The issue is that code which is not written to be tested, but instrumented with mocks and fixtures etc., is unaware that anyone else will have had the chance to configure logging before it runs, and thus blithely uses basicConfig (or other assumptions) as they are always workable, whether it's from import code or not. (The reason this module uses it from import code is that there are other things that happen at import time that may be useful to see logs about.)

I'm thinking of something like "patching logging.log and delaying until first log message" to address "capturing logs from applications whose code is not aware of any logging conflicts". It's tricky coding, but that's sort of what testing frameworks are all about, yeah?

[nicoddemus]

Hi @dmick thanks for bringing this to attention.

While I agree with @The-Compiler that in general functionality should not be initialized on import, it would be nice if we had an overview why the logging initialization changed the way it did, and if that use case should be supported.

If it is not technically possible to support it, we probably should document that, explaining the rationale and suggesting alternatives, as calling basicConfig at the module level seems to appear in many logging tutorials (however it is noteworthy that Python's own logging tutorial calls basicConfig inside a main function, not at the module level, but doesn't mention that is a recommended practice either).

@Thisch do you recall the rationale for this change?

[dmick]

Please note, however, as I pointed out in my last comment: import time isn't the only issue here. If pytest's logging initialization happens before import, then it surely happens before any main function in the module under test as well. If the module being tested initializes logging with basicConfig, it will fail whether that happens at import time or in a main or other method, because pytest got there first.

[a-recknagel]

I have a use case here: #11618

I've looked a bit into the source code since writing that post, and must admit defeat. I initially thought that it might be possible to attach the logic that enables log-collection onto the caplog fixture itself, so it would be possible to handle any issues in the test code itself. But after trying for a while to understand how _pytest.logging.catching_logs and item.stash works , I'd like to first ask if moving things around that way would provide any value, and if yes, be worth the hassle.