test_regrtest: test_huntrleaks() fails randomly: leaked [9, 1, 1] references

[vstinner]

Failure on GHA Windows x86 CI:

FAIL: test_huntrleaks (test.test_regrtest.ArgsTestCase.test_huntrleaks)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\a\cpython\cpython\Lib\test\test_regrtest.py", line 1068, in test_huntrleaks
    self.check_huntrleaks(run_workers=False)
  File "D:\a\cpython\cpython\Lib\test\test_regrtest.py", line 1065, in check_huntrleaks
    self.check_leak(code, 'references', run_workers=run_workers)
  File "D:\a\cpython\cpython\Lib\test\support\__init__.py", line 2564, in wrapper
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "D:\a\cpython\cpython\Lib\test\test_regrtest.py", line 1047, in check_leak
    self.assertIn(line2, output)
AssertionError:

'test_regrtest_huntrleaks leaked [1, 1, 1] references, sum=3\n' 

not found in

'0:00:00 Run 1 test sequentially\n
0:00:00 [1/1] test_regrtest_huntrleaks\n
beginning 6 repetitions\n
123456\n
......\n
test_regrtest_huntrleaks leaked [9, 1, 1] references, sum=11\n
test_regrtest_huntrleaks leaked [1, 1, 1] memory blocks, sum=3\n
test_regrtest_huntrleaks failed (reference leak)\n
\n
== Tests result: FAILURE ==\n
\n
1 test failed:\n
    test_regrtest_huntrleaks\n
\n
Total duration: 292 ms\n
Total tests: run=1\n
Total test files: run=1/1 failed=1\n
Result: FAILURE\n'

build: https://github.com/python/cpython/actions/runs/6274556366/job/17041487300?pr=109727

Linked PRs

• gh-109739: regrtest disables load tracker if refleak #109871

[vstinner]

Windows x64: https://github.com/python/cpython/actions/runs/6299520741/job/17100438819?pr=109831

[vstinner]

I cannot reproduce the issue on Linux. I stopped the stress test after 19 minutes:

vstinner@mona$ ./python -m test -v test_regrtest -m 'test_huntrleaks*' -v --forever -j10 -r
(...)
0:19:19 load avg: 11.84 [1770] test_regrtest passed

[vstinner]

I failed to reproduce the issue on Windows with this command:

vstinner@WIN C:\victor\python\main>python -m test -v test_regrtest -m test.test_regrtest.ArgsTestCase.test_huntrleaks -v --forever
(...)
0:17:19 load avg: 0.23 [1371] test_regrtest
test_huntrleaks (test.test_regrtest.ArgsTestCase.test_huntrleaks) ... ok

----------------------------------------------------------------------
Ran 1 test in 0.676s

OK

^C

I interrupted the test after 17 minutes.

[vstinner]

To reproduce the issue on Windows, create the file Lib\test\test_leak.py:

import unittest

GLOBAL_LIST = []

class RefLeakTest(unittest.TestCase):
    def test_leak(self):
        GLOBAL_LIST.append(object())

And run the script leak.py:

import sys
import subprocess

while True:
    sys.stdout.write(".")
    sys.stdout.flush()

    cmd = [sys.executable, "-m", "test", "-R", "3:3", "test_leak"]
    proc = subprocess.run(cmd,
                          stdout=subprocess.PIPE,
                          stderr=subprocess.STDOUT,
                          text=True)
    if "test_leak leaked [1, 1, 1] references" in proc.stdout:
        continue

    print(proc.stdout, end="")
    if proc.returncode:
        print(f"FAILED: exit code {proc.returncode}")
        break

[vstinner]

And run the script leak.py:

And more the system less determistic by running the following command in a different terminal:

python -m test -j1 -r --forever

Example of the bug on Windows:

vstinner@WIN C:\victor\python\main>python leak.py
Running Debug|x64 interpreter...
........................0:00:00 Run 1 test sequentially
0:00:00 [1/1] test_leak
beginning 6 repetitions
123456
......
test_leak leaked [9, 1, 1] references, sum=11
test_leak leaked [1, 1, 1] memory blocks, sum=3
test_leak failed (reference leak)

== Tests result: FAILURE ==

1 test failed:
    test_leak

Total duration: 237 ms
Total tests: run=1
Total test files: run=1/1 failed=1
Result: FAILURE
FAILED: exit code 2

[vstinner]

I can still reproduce the leak even if I disable the bytecode specialization.

diff --git a/Include/internal/pycore_code.h b/Include/internal/pycore_code.h
index a77fa11baf..7de6384574 100644
--- a/Include/internal/pycore_code.h
+++ b/Include/internal/pycore_code.h
@@ -236,7 +236,7 @@ extern int _PyLineTable_PreviousAddressRange(PyCodeAddressRange *range);
 /** API for executors */
 extern void _PyCode_Clear_Executors(PyCodeObject *code);

-#define ENABLE_SPECIALIZATION 1
+#define ENABLE_SPECIALIZATION 0

 /* Specialization functions */

[vstinner]

"before" variables when the bug occurs:

test_leak leaked [9, 1, 1] references, sum=11
test_leak leaked [1, 1, 1] memory blocks, sum=3
interned_before=12109
alloc_before=61013
rc_before=94336
fd_before=3

"before" variables when the bug does not occur:

interned_before=12109
alloc_before=61013
rc_before=94333
fd_before=3
test_leak leaked [1, 1, 1] references, sum=3

Only rc_before is different: 94 333 (ok) => 94 336 (bug).

[vstinner]

Oooooooh, the issue comes from regrtest logger: from WindowsLoadTracker thread.