From 672b551b0a6e3267854e61d6476255f3ca02d3b7 Mon Sep 17 00:00:00 2001 From: marcelomarkus Date: Thu, 13 Aug 2026 08:26:55 -0300 Subject: [PATCH 1/2] fix: correct timing information for subtests when using console_output_style=times (#14412) When console_output_style="times" is used with subtests, subtest timing information and parent test PASSED reports were displayed with incorrect/zero durations. This change includes subtest reports in terminal reporter aggregation and tracks reported durations by object identity rather than nodeid. Fixes #14412. Co-authored-by: Shimon Schwartz Co-authored-by: Antigravity --- AUTHORS | 2 ++ changelog/14412.bugfix.rst | 1 + src/_pytest/terminal.py | 19 ++++++++--- testing/test_terminal.py | 64 ++++++++++++++++++++++++++++++++++++++ 4 files changed, 82 insertions(+), 4 deletions(-) create mode 100644 changelog/14412.bugfix.rst diff --git a/AUTHORS b/AUTHORS index 33ee644ea68..a2f001750cc 100644 --- a/AUTHORS +++ b/AUTHORS @@ -296,6 +296,7 @@ Manuel Krebber Marc Mueller Marc Schlaich Marcelo Duarte Trevisani +Marcelo Markus Marcin Augustynów Marcin Bachry Marc Bresson @@ -442,6 +443,7 @@ Seth Junot Shantanu Jain Sharad Nair Shaygan Hooshyari +Shimon Schwartz Shubham Adep Simon Blanchard Simon Gomizelj diff --git a/changelog/14412.bugfix.rst b/changelog/14412.bugfix.rst new file mode 100644 index 00000000000..4148ca8b454 --- /dev/null +++ b/changelog/14412.bugfix.rst @@ -0,0 +1 @@ +Fixed incorrect timing information for subtests and parent tests when ``console_output_style="times"``. diff --git a/src/_pytest/terminal.py b/src/_pytest/terminal.py index b9a65ff191e..288616cea51 100644 --- a/src/_pytest/terminal.py +++ b/src/_pytest/terminal.py @@ -401,7 +401,8 @@ def __init__(self, config: Config, file: TextIO | None = None) -> None: # We use CallableBool here to support both. self.isatty = compat.CallableBool(file.isatty()) self._progress_nodeids_reported: set[str] = set() - self._timing_nodeids_reported: set[str] = set() + self._timing_nodeids_reported: set[int] = set() + self._current_logreport: TestReport | None = None self._show_progress_info = self._determine_show_progress_info() self._collect_report_last_write = timing.Instant() self._already_displayed_warnings: int | None = None @@ -623,6 +624,7 @@ def pytest_runtest_logstart( self.flush() def pytest_runtest_logreport(self, report: TestReport) -> None: + self._current_logreport = report self._tests_ran = True rep = report @@ -739,9 +741,18 @@ def _get_progress_information_message(self) -> str: + self._get_reports_to_display("error") + self._get_reports_to_display("") ) - current_location = all_reports[-1].location[0] + for key in self.stats: + if key.startswith("subtests "): + all_reports.extend(self._get_reports_to_display(key)) + + report = self._current_logreport + if report is not None: + current_location = report.location[0] + else: + current_location = all_reports[-1].location[0] if all_reports else "" + not_reported = [ - r for r in all_reports if r.nodeid not in self._timing_nodeids_reported + r for r in all_reports if id(r) not in self._timing_nodeids_reported ] tests_in_module = sum( i.location[0] == current_location for i in self._session.items @@ -753,7 +764,7 @@ def _get_progress_information_message(self) -> str: ) last_in_module = tests_completed == tests_in_module if self.showlongtestinfo or last_in_module: - self._timing_nodeids_reported.update(r.nodeid for r in not_reported) + self._timing_nodeids_reported.update(id(r) for r in not_reported) return format_node_duration( sum(r.duration for r in not_reported if isinstance(r, TestReport)) ) diff --git a/testing/test_terminal.py b/testing/test_terminal.py index 3053f5ef9a1..5d4cfcca780 100644 --- a/testing/test_terminal.py +++ b/testing/test_terminal.py @@ -140,6 +140,70 @@ def test_hello(): combined = "\n".join(result.stdout.lines + result.stderr.lines) assert "INTERNALERROR" not in combined + def test_console_output_style_times_with_subtests(self, pytester: Pytester) -> None: + pytester.makepyfile( + test_repro=""" + def test_subtests(subtests): + for i in range(2): + with subtests.test(i=i): + pass + """ + ) + result = pytester.runpytest( + "test_repro.py", + "-v", + "-o", + "console_output_style=times", + "-o", + "verbosity_subtests=1", + ) + + # Check that we got positive/non-zero timing info for subtests and the parent PASSED line. + # We check that it does not show "0.000us". + lines = result.stdout.lines + subpassed_lines = [ + line_content for line_content in lines if "SUBPASSED" in line_content + ] + passed_lines = [ + line_content + for line_content in lines + if "PASSED" in line_content and "SUBPASSED" not in line_content + ] + assert len(subpassed_lines) == 2 + assert len(passed_lines) == 1 + for line in subpassed_lines + passed_lines: + assert "0.000us" not in line + + def test_progress_information_message_no_current_report( + self, pytester: Pytester, monkeypatch: pytest.MonkeyPatch + ) -> None: + item = pytester.getitem("def test_func(): pass") + tr = TerminalReporter(item.config) + monkeypatch.setattr(tr.config, "get_verbosity", lambda *args, **kwargs: 1) + tr._show_progress_info = "times" + + class MockSession: + testscollected = 1 + items = [item] + + tr._session = MockSession() # type: ignore[assignment] + + from _pytest.reports import TestReport + + rep = TestReport( + nodeid=item.nodeid, + location=item.location, + keywords={}, + outcome="passed", + longrepr=None, + when="call", + duration=0.123, + ) + tr.stats.setdefault("passed", []).append(rep) + + msg = tr._get_progress_information_message() + assert msg == " 123.0ms" + def test_internalerror(self, pytester: Pytester, linecomp) -> None: modcol = pytester.getmodulecol("def test_one(): pass") rep = TerminalReporter(modcol.config, file=linecomp.stringio) From 4e07f4c089d7481b25bc13f721d877916fec00d3 Mon Sep 17 00:00:00 2001 From: marcelomarkus Date: Thu, 13 Aug 2026 17:20:05 -0300 Subject: [PATCH 2/2] fix(terminal): rename _timing_nodeids_reported to _timing_report_ids_reported and add xdist test --- src/_pytest/terminal.py | 6 +++--- testing/test_terminal.py | 37 +++++++++++++++++++++++++++++++++++++ 2 files changed, 40 insertions(+), 3 deletions(-) diff --git a/src/_pytest/terminal.py b/src/_pytest/terminal.py index 664ac3ecea0..37e20fc7026 100644 --- a/src/_pytest/terminal.py +++ b/src/_pytest/terminal.py @@ -408,7 +408,7 @@ def __init__(self, config: Config, file: TextIO | None = None) -> None: # We use CallableBool here to support both. self.isatty = compat.CallableBool(file.isatty()) self._progress_nodeids_reported: set[str] = set() - self._timing_nodeids_reported: set[int] = set() + self._timing_report_ids_reported: set[int] = set() self._current_logreport: TestReport | None = None self._show_progress_info = self._determine_show_progress_info() self._collect_report_last_write = timing.Instant() @@ -762,7 +762,7 @@ def _get_progress_information_message(self) -> str: current_location = all_reports[-1].location[0] if all_reports else "" not_reported = [ - r for r in all_reports if id(r) not in self._timing_nodeids_reported + r for r in all_reports if id(r) not in self._timing_report_ids_reported ] tests_in_module = sum( i.location[0] == current_location for i in self._session.items @@ -774,7 +774,7 @@ def _get_progress_information_message(self) -> str: ) last_in_module = tests_completed == tests_in_module if self.showlongtestinfo or last_in_module: - self._timing_nodeids_reported.update(id(r) for r in not_reported) + self._timing_report_ids_reported.update(id(r) for r in not_reported) return format_node_duration( sum(r.duration for r in not_reported if isinstance(r, TestReport)) ) diff --git a/testing/test_terminal.py b/testing/test_terminal.py index 1d38d7effdd..241e738b601 100644 --- a/testing/test_terminal.py +++ b/testing/test_terminal.py @@ -174,6 +174,43 @@ def test_subtests(subtests): for line in subpassed_lines + passed_lines: assert "0.000us" not in line + def test_console_output_style_times_with_subtests_xdist( + self, pytester: Pytester, monkeypatch: pytest.MonkeyPatch + ) -> None: + pytest.importorskip("xdist") + monkeypatch.delenv("PYTEST_DISABLE_PLUGIN_AUTOLOAD", raising=False) + pytester.makepyfile( + test_repro=""" + def test_subtests(subtests): + for i in range(2): + with subtests.test(i=i): + pass + """ + ) + result = pytester.runpytest( + "test_repro.py", + "-n2", + "-v", + "-o", + "console_output_style=times", + "-o", + "verbosity_subtests=1", + ) + + lines = result.stdout.lines + subpassed_lines = [ + line_content for line_content in lines if "SUBPASSED" in line_content + ] + passed_lines = [ + line_content + for line_content in lines + if "PASSED" in line_content and "SUBPASSED" not in line_content + ] + assert len(subpassed_lines) == 2 + assert len(passed_lines) == 1 + for line in subpassed_lines + passed_lines: + assert "0.000us" not in line + def test_progress_information_message_no_current_report( self, pytester: Pytester, monkeypatch: pytest.MonkeyPatch ) -> None: