test_multiprocessing_forkserver.py, test_multiprocessing_fork.py and test_multiprocessing_spawn.py gives tracebacks

[sharewax]

Bug report

During build RPM for python3.11rc1 I've found tracebacks for tests from test suite test_multiprocessing_forkserver.py, test_multiprocessing_fork.py, and test_multiprocessing_spawn.py :

[root@xxx test]# python3.11 test_multiprocessing_forkserver.py
............s..................................................s...............................s.s.s.....s...s...........ss.....s......................................................................................................................................Traceback (most recent call last):
  File "/opt/rh/rh-python311/root/usr/lib64/python3.11/multiprocessing/resource_tracker.py", line 209, in main
.    cache[rtype].remove(name)
KeyError: '/psm_8714e59f'
..............................ssss...............................s.........ss.ss..sss.sss.s.ssss......ss....s.
----------------------------------------------------------------------
Ran 374 tests in 75.001s

OK (skipped=33)
[root@xxx test]# python3.11 test_multiprocessing_spawn.py
............s..............s...................................s...............................s.s.s.....s...s...........ss.....s...............................................................................................ss.....................................Traceback (most recent call last):
  File "/opt/rh/rh-python311/root/usr/lib64/python3.11/multiprocessing/resource_tracker.py", line 209, in main
.    cache[rtype].remove(name)
KeyError: '/psm_e93c9b17'
..............................ssss...............................s.........ss.ss..sss.sss.s.ssss......ss....s.
----------------------------------------------------------------------
Ran 374 tests in 118.379s

OK (skipped=36)

[root@xxx test]# python3.11 test_multiprocessing_fork.py
............s..............s...................................s...............................s.s.s.....s...s...........ss.....s........................................................................................s......ss.....................................Traceback (most recent call last):
  File "/opt/rh/rh-python311/root/usr/lib64/python3.11/multiprocessing/resource_tracker.py", line 209, in main
.    cache[rtype].remove(name)
KeyError: '/psm_1324c68a'
..............................ssss...............................s.........ss.ss..sss.sss.s.ssss......ss....s.
----------------------------------------------------------------------
Ran 374 tests in 67.935s

OK (skipped=37)

I suppose, that tracebacks are not ok during test. Or close the bug, if it normal.
Some KeyError are present in #95396.

Your environment

Python 3.11.0rc1 (main, Aug 13 2022, 18:23:13) [GCC 9.3.1 20200408 (Red Hat 9.3.1-2)] on linux
Centos7 x86_64, python 3.11rc1

[serhiy-storchaka]

I seen this output many times, but cannot reproduce locally (on Ubuntu).

It is bad because it looks like an error even if test reports OK. It is mixed with real errors report and make it more difficult to analyze. It can also be a symptom of a problem with resource management.

[sharewax]

As for KeyError psm it looks like issues with shared memory. Some things was discussed in #91577.
I see that in commit 9a458be was added resource_tracker, maybe it's connected somehow.

[sharewax]

shared_memory.py

...
            try:
                if create and size:
                    os.ftruncate(self._fd, size)
                stats = os.fstat(self._fd)
                size = stats.st_size
                self._mmap = mmap.mmap(self._fd, size)
            except OSError:
                self.unlink()
                raise

            resource_tracker.register(self._name, "shared_memory")

So if OSError exist, it tries to do resource_tracker.unregister which is contained in self.unlink(), but maybe it can be situation when resource_tracker.register wasn't register before?

[sharewax]

maybe connected with #89372 ?
I've found the test which reproduce this traceback

python -m test -v test_multiprocessing_forkserver -m test_shared_memory_cleaned_after_process_termination
== CPython 3.11.0rc1 (main, Aug 13 2022, 18:23:13) [GCC 9.3.1 20200408 (Red Hat 9.3.1-2)]
== Linux-3.10.0-1160.62.1.el7.x86_64-x86_64-with-glibc2.17 little-endian
== cwd: /tmp/test_python_43253æ
== CPU count: 40
== encodings: locale=UTF-8, FS=utf-8
0:00:00 load avg: 21.34 Run tests sequentially
0:00:00 load avg: 21.34 [1/1] test_multiprocessing_forkserver
test_shared_memory_cleaned_after_process_termination (test.test_multiprocessing_forkserver.WithProcessesTestSharedMemory.test_shared_memory_cleaned_after_process_termination) ... Traceback (most recent call last):
  File "/opt/rh/rh-python311/root/usr/lib64/python3.11/multiprocessing/resource_tracker.py", line 209, in main
ok
    cache[rtype].remove(name)
KeyError: '/psm_60e6d44e'

----------------------------------------------------------------------
Ran 1 test in 0.235s

OK

== Tests result: SUCCESS ==

1 test OK.

Total duration: 420 ms
Tests result: SUCCESS

it is reproducable for test_multiprocessing_fork, test_multiprocessing_forkserver, test_multiprocessing_spawn

In my case reverting patch f604cf1 doesn't produce any key error and other UserWarning.
So it's like specific for Windows tests?
Checked on current MacOS:

python3.10 -m test -v test_multiprocessing_spawn -v -m test_shared_memory_cleaned_after_process_termination
Raised RLIMIT_NOFILE: 256 -> 1024
== CPython 3.10.6 (main, Aug 6 2022, 22:42:17) [Clang 13.1.6 (clang-1316.0.21.2.5)]
== macOS-12.5-x86_64-i386-64bit little-endian
== cwd: /private/var/folders/pr/4ktlw3_s2bxfb3ggg496dc1h0000gp/T/test_python_92918æ
== CPU count: 8
== encodings: locale=UTF-8, FS=utf-8
0:00:00 load avg: 1.90 Run tests sequentially
0:00:00 load avg: 1.90 [1/1] test_multiprocessing_spawn
test_shared_memory_cleaned_after_process_termination (test.test_multiprocessing_spawn.WithProcessesTestSharedMemory) ... ok
unregister /psm_9b1c91a5
Traceback (most recent call last):
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.10/lib/python3.10/multiprocessing/resource_tracker.py", line 211, in main
    cache[rtype].remove(name)
KeyError: '/psm_9b1c91a5'

----------------------------------------------------------------------
Ran 1 test in 0.237s

OK

== Tests result: SUCCESS ==

1 test OK.

Total duration: 373 ms
Tests result: SUCCESS

it tries to run resource_tracker.unregister on the resource which wasn't added into resource_tracker before.

0:00:00 load avg: 20.19 [1/1] test_multiprocessing_spawn
test_shared_memory_cleaned_after_process_termination (test.test_multiprocessing_spawn.WithProcessesTestSharedMemory.test_shared_memory_cleaned_after_process_termination) ... b'REGISTER:/mp-kxz5k9_d:semaphore\n'
register /mp-kxz5k9_d
b'PROBE:0:noop\n'
b'UNREGISTER:/mp-kxz5k9_d:semaphore\n'
unregister /mp-kxz5k9_d
resource_tracker.unregister name is: psm_674b5480
b'PROBE:0:noop\n'
b'UNREGISTER:/psm_674b5480:shared_memory\n'
unregister /psm_674b5480
Traceback (most recent call last):
  File "/opt/rh/rh-python311/root/usr/lib64/python3.11/multiprocessing/resource_tracker.py", line 212, in main
ok
    cache[rtype].remove(name)
KeyError: '/psm_674b5480'

----------------------------------------------------------------------
Ran 1 test in 0.220s

[sergeykolosov]

I'm not entirely confident yet, but it appears that after 9a458be got merged, the workaround from f604cf1 is no longer needed (and causes the reported issue).

[sharewax]

@tiran is it possible to fix it by reverting workaround as mentioned in comment by @sergeykolosov ?

[tiran]

@sharewax Please refrain from pinging core developers on issues to draw their attention. It's distracting. Triagers may ping core devs or assign tickets that are listed as experts in https://devguide.python.org/core-developers/experts/index.html.

[sharewax]

sorry for that :(

[codeofandrin]

Also encountered this problem for Python 3.9.21 on macOS arm64.