pytest-dev / pytest-dev/pytest
pytest log init timing changed; now code-under-test with logging.basicConfig fails
Nobody has claimed this yet.
- Dominant language
- Python
- Stars
- 14.5k
- Forks
- 3.4k
- Avg merge
- 2d 9h
- Merged PRs (30d)
- 35
Description
Discussed in https://github.com/pytest-dev/pytest/discussions/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.
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start by reproducing the change between pytest 3.7.1 and 6.2.5, focusing on pytest's logging initialization, logging.basicConfig(), and caplog.records. Review the linked discussion for the unresolved design question; done should preserve application logging configuration while retaining pytest's ability to capture logs, with coverage for the LogRecord.asctime behavior.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python
- Domain
- testing
- Issue type
- Bug
- Difficulty
- 5/5
- Estimated time
- Over a week
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100