Bugfix 14412 subtests timing

[marcelomarkus]

Summary

Fixes #14412.

When using console_output_style="times" and running subtests, timing information for subtests and the parent test's PASSED report could be displayed incorrectly (e.g. 0.000us or missing).

This occurs because subtests share their parent test's nodeid. In console_output_style="times", timing output suppresses subsequent reports for the same nodeid once marked as reported, and subtest reports were not handled as distinct progress lines.

Solution

This PR resolves the issue by:

1. Tracking the current report in pytest_runtest_logreport via self._current_logreport.
2. Handling SubtestReport directly in _write_progress_information_times(): when the current report is a SubtestReport, its own duration is formatted and returned directly (when self.showlongtestinfo is enabled) without modifying _timing_nodeids_reported.
3. Retaining _timing_nodeids_reported tracking by nodeid to ensure teardown timing does not leak into subsequent test lines.
4. Excluding SubtestReport instances from the not_reported accumulation list, ensuring subtest durations are not counted twice in per-module timing totals.
5. Using self._current_logreport.location[0] (with fallback to all_reports[-1].location[0]) to ensure accurate module location tracking.

Regression tests have been added to verify subtest timing with and without xdist, as well as ensuring slow fixture teardowns do not leak into the next test line.

Attribution

This pull request was implemented with assistance from AI coding tools (Antigravity), credited via the Co-authored-by trailer in the commit history according to pytest's contribution guidelines.

Co-authored-by: Shimon Schwartz (@shimonenator)
Co-authored-by: Antigravity

[RonnyPfannschmidt]

missing attributions

[marcelomarkus]

Updated the PR description with attributions (including AI co-author trailers and credits for @shimonenator) and checked the PR checklist. Thanks!

[RonnyPfannschmidt]

🤖 Written by Claude Opus 5.5 via Claude Code for the pytest maintainers; I prompted it, it did the work, I read it.

Thanks for chasing this down. The bug is real, and keying on nodeid alone can't handle subtests because they share their parent's nodeid. But switching the dedup to id(r) introduces a regression, and I don't think any new key is needed.

Reproduction (-v -o console_output_style=times -o verbosity_subtests=1, main vs this PR's head 71e80dd):

# test_a.py
import time, pytest
@pytest.fixture
def slow_td():
    yield
    time.sleep(0.5)
def test_a1(slow_td): pass
def test_a2(): pass

# test_c.py
@pytest.fixture(scope="module")
def mod_td():
    yield
    time.sleep(0.5)
def test_c1(mod_td): pass

# test_b.py
def test_b1(): pass

# test_s.py
def test_sub(subtests):
    for i in range(2):
        with subtests.test(i=i):
            time.sleep(0.1)

	main	this PR
test_a2 PASSED	165us	501.2ms (the teardown of test_a1)
test_b1 PASSED after test_c.py	217us	500.7ms (the module teardown of test_c.py)
SUBPASSED(i=0) / (i=1) / parent PASSED	290us / 0.000us / 0.000us	101ms / 101ms / 203ms

1. Teardown time leaks into the next line. On main, the teardown report is skipped because its nodeid was already marked as reported when the call line was printed. With id(r), a teardown that arrives after its line was printed stays "not reported", so it gets added to whatever line prints next: the next test, or the first test of the next module.
2. Subtest durations get counted twice in per-module mode. test_s.py prints about 405ms for about 200ms of actual work, because each subtest's duration is already part of the parent's call duration. Main has the same problem in quiet subtests mode, since those reports land in the "" category. Adding the subtests * categories to all_reports doesn't fix it.
3. key.startswith("subtests ") makes terminal.py depend on the category strings the subtests plugin uses.

Suggested approach: keep _timing_nodeids_reported as it is. In verbose times mode, when the report being printed is a SubtestReport, return its own duration and don't touch the set. Your _current_logreport is the right hook for that check. Applying roughly this on top of main:

if isinstance(self._current_logreport, SubtestReport):
    if self.showlongtestinfo:
        return format_node_duration(self._current_logreport.duration)
    return ""

gives SUBPASSED 100.7ms / 100.7ms, parent PASSED 202.9ms, and no teardown leak (test_a2 165us, test_b1 217us). I checked this only against the scenarios above, not the full test suite. Point 2 is older than this PR and could be handled separately.

A test with a slow teardown fixture, asserting the next test's line stays small, would catch the regression in point 1.

---

Generated by Claude Code

[marcelomarkus]

Thanks @RonnyPfannschmidt!

I've adopted your suggested approach and added the slow teardown regression test you mentioned. Ready for another look!

[RonnyPfannschmidt]

🤖 Written by Claude Opus 5.5 via Claude Code for the pytest maintainers; I prompted it, it did the work, I read it.

Thanks! I reran the earlier reproduction on 9ea524e. Teardown time no longer leaks into the next test, subtest lines show their own duration, and the per-module totals no longer count subtest time twice.

Before merge, please update the PR description to match the code. It still says the fix tracks reports by id(r) and includes the "subtests " categories, but the code now keeps the nodeid tracking, prints a SubtestReport's own duration, and leaves subtest reports out of the timing sums.

---

Generated by Claude Code

[marcelomarkus]

@RonnyPfannschmidt Done! I've updated the PR description to match the current implementation. Thanks!