Keep --log-cli-level from increasing verbosity - #14667
ishaanlabs-gg wants to merge 4 commits into
Conversation
faee8c8 to
52e751f
Compare
|
What happens to loggin the current test item with that being done Life log needs separation as ux |
|
Adjusted this so explicit Validation:
|
for more information, see https://pre-commit.ci
RonnyPfannschmidt
left a comment
There was a problem hiding this comment.
Attribution: I prompted an exploration of this PR with Claude Opus 5 running in Claude Code. The agent set up the worktrees, ran every comparison below, produced the output samples, and wrote this analysis. I have read it and I stand behind it, and I am posting it as my review — but the exploring was the agent's, not mine. Where it says "the agent ran X", that is literal.
Thanks for picking this up — #13612 is a real complaint and the direction here is right. There is a problem with the implementation though, and I would like it addressed before this lands.
Everything below was checked against your head commit a6c107f26 and again rebased onto current main.
1. The output ends up messier than what it replaces
This is the blocking one. _LiveLoggingStreamHandler.emit calls self.stream.write_ensure_prefix(self._test_item_line, ""), and write_ensure_prefix assigns that str to TerminalReporter.currentfspath. The non-verbose progress path, write_fspath_result, compares currentfspath against a Path:
fspath = self.config.rootpath / nodeid.split("::", maxsplit=1)[0]
if self.currentfspath is None or fspath != self.currentfspath:A str never equals a Path, so the reporter concludes the file changed and re-emits the filename header plus a progress-filling percentage — once per test that logs.
The agent ran this file:
import logging
log = logging.getLogger(__name__)
def test_a():
log.warning("warn from a")
def test_b():
pass
def test_c():
log.warning("warn from c")
log.warning("second warn from c")
def test_d():
pass
def test_fail():
log.warning("warn before failure")
assert FalseWith this PR, pytest --log-cli-level=WARNING:
collected 5 items
test_demo.py
test_demo.py::test_a
-------------------------------- live log call ---------------------------------
WARNING test_demo:test_demo.py:7 warn from a
. [ 20%]
test_demo.py .
test_demo.py::test_c
-------------------------------- live log call ---------------------------------
WARNING test_demo:test_demo.py:15 warn from c
WARNING test_demo:test_demo.py:16 second warn from c
. [ 60%]
test_demo.py .
test_demo.py::test_fail
-------------------------------- live log call ---------------------------------
WARNING test_demo:test_demo.py:24 warn before failure
F [100%]
test_demo.py is reprinted for every logging test, the dot run is shredded across lines, and a percentage is stamped mid-stream after each test instead of at the line end. That is worse than the status quo this is replacing.
Same mechanism with fixture logging — the outcome character lands between the setup and teardown blocks, and a percentage ends up alone on a line:
test_setup.py
test_setup.py::test_s
-------------------------------- live log setup --------------------------------
WARNING test_setup:test_setup.py:6 setup log
.
------------------------------ live log teardown -------------------------------
WARNING test_setup:test_setup.py:8 teardown log
[ 50%]
test_setup.py . [100%]
Worth flagging: the change to test_log_cli_auto_enable bakes this in as expected output. It now asserts both "test_log_cli_auto_enable.py " and "*::test_log_1 " — that pair is the duplicated header. With a single test in a single file the duplication looks harmless, which is why the test passes; it only becomes obvious at more than one test.
It is close to fixable
Saving and restoring currentfspath around the prefix write is enough:
saved = self.stream.currentfspath
self.stream.write_ensure_prefix(self._test_item_line, "")
self.stream.currentfspath = savedThe agent applied exactly that on top of the rebased branch and re-ran the same file:
collected 5 items
test_demo.py
test_demo.py::test_a
-------------------------------- live log call ---------------------------------
WARNING test_demo:test_demo.py:7 warn from a
..
test_demo.py::test_c
-------------------------------- live log call ---------------------------------
WARNING test_demo:test_demo.py:15 warn from c
WARNING test_demo:test_demo.py:16 second warn from c
..
test_demo.py::test_fail
-------------------------------- live log call ---------------------------------
WARNING test_demo:test_demo.py:24 warn before failure
F [100%]
Dot run intact, one percentage at the end, one file header. The fixture case comes out right too.
Two follow-ups on that, and the second is the actual design question in this PR:
- Even fixed, the leading
test_demo.pyheader and thetest_demo.py::test_aline say the same thing. Once per file it is tolerable, but a domain-only line from the handler might read better than the full_locationline. - Reaching into
stream.currentfspathfrom the logging plugin is grubby. The handler already reaches for_locationline, so this is not a new sin, but it deepens a coupling I am not keen on. I would rather see a small helper onTerminalReporter— something likewrite_transient_prefix— that owns the save/restore, than havelogging.pyhand-managing reporter state. Happy to discuss the shape if you want to go that way; I can also take that part myself if you would prefer to keep this PR narrow.
2. ini + CLI together drops the bump, contrary to the PR description
The description says this "keeps the existing verbosity bump for log_cli=true, but skips it when live logging is enabled only by the --log-cli-level command-line option". The code does not implement the "only":
if self._config.getoption("--log-cli-level") is None:
self._config.option.verbose = 1_log_cli_enabled() is true if either --log-cli-level is given or the log_cli ini is set. So with log_cli = true in the ini and --log-cli-level=WARNING on the command line, the option is non-None and the bump is dropped. A log_cli=true user silently loses their verbose progress just by overriding the level for one run.
The agent confirmed it: log_cli=true in the ini alone keeps PASSED [ 14%]; adding --log-cli-level=WARNING on top switches to the compact form.
If the stated rule is the intended one, the condition needs and not self._config.getini("log_cli") as well. If the real intent is "compact unless the user asked for verbose", then say so in the description — but dropping the log_cli=true bump is a behaviour change for existing ini users and wants its own decision and changelog line, not a side effect.
3. Does not type-check after rebase
This branches off 1aa747de6, 277 commits back. #14758 landed in between and changed TerminalReporter._locationline to take a NodeId rather than a str.
The rebase itself is clean and the suite passes, but:
src/_pytest/logging.py:950: error: Argument 1 to "_locationline" of "TerminalReporter"
has incompatible type "str"; expected "NodeId" [arg-type]
It survives at runtime by accident. Needs NodeId.parse(nodeid), plus a rebase so CI is telling you the truth.
Smaller things
set_test_itemis called frompytest_runtest_logstartfor every test and eagerly formats_locationline, even when_show_test_itemis false (thelog_cli=trueini path) or when no record is ever emitted. Storing the(nodeid, location)pair and formatting lazily insideemitwould avoid that.-q --log-cli-level=WARNINGchanges behaviour too: today the verbosity bump overrides-qentirely, whereas this PR honours it. That is arguably an improvement, but it is a second user-visible change that is not in the changelog.test_live_logging_null_handler_accepts_test_item_hookshas no assertions — it can only fail onAttributeError. That is a thin test for a no-op shim.test_log_cli_level_option_keeps_default_verbositydrives the hook generator by hand with aSimpleNamespacecast toSession. That will break on unrelated refactors; apytester.runpytestasserting on actual output would hold up better and would have caught issue 1.- The changelog entry only mentions verbosity. The presentation of live logs also changes — the item line is now written from the log handler — and that deserves a mention.
For the record, on why the item line belongs here at all
The agent also built the naive variant (the verbosity guard, none of the location-line machinery) to see what is lost:
test_demo.py
-------------------------------- live log call ---------------------------------
WARNING test_demo:test_demo.py:7 warn from a
..
-------------------------------- live log call ---------------------------------
WARNING test_demo:test_demo.py:15 warn from c
Clean, but you cannot tell which test produced the block — only the logger's own module:file:lineno. That is precisely the "messy test progress output" the original comment was guarding against, so adding the lazy item line is the right call. It just has to stop fighting currentfspath.
Requesting changes on: the currentfspath restore (or a reporter-side helper), the ini+CLI condition, NodeId.parse, and a rebase onto main. With those it is a genuine improvement and I would like to see it in.
Fixes #13612.
--log-cli-levelcurrently enables live logging and then raises the global verbosity to1, which makes normal test progress look like-vwas passed. This keeps the existing verbosity bump forlog_cli=true, but skips it when live logging is enabled only by the--log-cli-levelcommand-line option.Validation:
PYTHONPATH=src .venv-codex/bin/python -m pytest testing/logging/test_reporting.py -qgit diff --check