Skip to content

Keep --log-cli-level from increasing verbosity - #14667

Open
ishaanlabs-gg wants to merge 4 commits into
pytest-dev:mainfrom
ishaanlabs-gg:fix-log-cli-level-verbosity
Open

ishaanlabs-gg wants to merge 4 commits into
pytest-dev:mainfrom
ishaanlabs-gg:fix-log-cli-level-verbosity

Conversation

@ishaanlabs-gg

Copy link
Copy Markdown
Contributor

Fixes #13612.

--log-cli-level currently enables live logging and then raises the global verbosity to 1, which makes normal test progress look like -v was passed. 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.

Validation:

  • PYTHONPATH=src .venv-codex/bin/python -m pytest testing/logging/test_reporting.py -q
  • git diff --check

@psf-chronographer psf-chronographer Bot added the bot:chronographer:provided (automation) changelog entry is part of PR label Jul 1, 2026
@ishaanlabs-gg
ishaanlabs-gg force-pushed the fix-log-cli-level-verbosity branch from faee8c8 to 52e751f Compare July 1, 2026 00:08
@RonnyPfannschmidt

Copy link
Copy Markdown
Member

What happens to loggin the current test item with that being done

Life log needs separation as ux

@ishaanlabs-gg

Copy link
Copy Markdown
Contributor Author

Adjusted this so explicit --log-cli-level keeps compact result reporting but still prints the current test item before the first live log record from that item. So live logging now has item context/separation without restoring verbose PASSED outcome lines for every test.

Validation:

  • .venv-codex/bin/python -m pytest testing/logging/test_reporting.py -q -k 'log_cli_level or log_cli_auto_enable'\n- .venv-codex/bin/python -m pytest testing/logging/test_reporting.py -q\n\nI also attempted the local Ruff checks, but this checkout venv does not currently have ruff installed.

@RonnyPfannschmidt RonnyPfannschmidt left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 False

With 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 = saved

The 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.py header and the test_demo.py::test_a line 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.currentfspath from 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 on TerminalReporter — something like write_transient_prefix — that owns the save/restore, than have logging.py hand-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_item is called from pytest_runtest_logstart for every test and eagerly formats _locationline, even when _show_test_item is false (the log_cli=true ini path) or when no record is ever emitted. Storing the (nodeid, location) pair and formatting lazily inside emit would avoid that.
  • -q --log-cli-level=WARNING changes behaviour too: today the verbosity bump overrides -q entirely, 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_hooks has no assertions — it can only fail on AttributeError. That is a thin test for a no-op shim.
  • test_log_cli_level_option_keeps_default_verbosity drives the hook generator by hand with a SimpleNamespace cast to Session. That will break on unrelated refactors; a pytester.runpytest asserting 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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

bot:chronographer:provided (automation) changelog entry is part of PR

Projects

None yet

Development

Successfully merging this pull request may close these issues.

--log-cli-level also increases verbosity level

2 participants