test_multiprocessing_fork fails if run sequentially after test_genericalias and test_logging

[pablogsal]

BPO	45128
Nosy	@vstinner, @ambv, @pablogsal, @miss-islington, @kanavin, @sobolevn
PRs	bpo-45128: fixes test_multiprocessing_fork mysterious crash #28387 [3.10] bpo-45128: fixes test_multiprocessing_fork mysterious crash (GH-28387) #28462

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2021-09-19.23:34:08.602>
created_at = <Date 2021-09-07.14:33:53.106>
labels = ['tests', '3.10']
title = 'test_multiprocessing_fork fails if run sequentially after test_genericalias and test_logging'
updated_at = <Date 2021-10-04.19:18:43.128>
user = 'https://github.com/pablogsal'

bugs.python.org fields:

activity = <Date 2021-10-04.19:18:43.128>
actor = 'pablogsal'
assignee = 'none'
closed = True
closed_date = <Date 2021-09-19.23:34:08.602>
closer = 'pablogsal'
components = ['Tests']
creation = <Date 2021-09-07.14:33:53.106>
creator = 'pablogsal'
dependencies = []
files = []
hgrepos = []
issue_num = 45128
keywords = ['patch']
message_count = 15.0
messages = ['401287', '401291', '401332', '401333', '401846', '401855', '401925', '401928', '401929', '401930', '401931', '402178', '402183', '402199', '403165']
nosy_count = 6.0
nosy_names = ['vstinner', 'lukasz.langa', 'pablogsal', 'miss-islington', 'Alexander Kanavin', 'sobolevn']
pr_nums = ['28387', '28462']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue45128'
versions = ['Python 3.10']

[pablogsal]

While testing the release artifacts I encountered this failure:

test test_multiprocessing_fork failed -- Traceback (most recent call last):
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/unittest/mock.py", line 1239, in _dot_lookup
    return getattr(thing, comp)
AttributeError: module 'multiprocessing' has no attribute 'shared_memory'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/test/_test_multiprocessing.py", line 3818, in test_shared_memory_basics
    with unittest.mock.patch(
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/unittest/mock.py", line 1422, in __enter__
    self.target = self.getter()
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/unittest/mock.py", line 1609, in <lambda>
    getter = lambda: _importer(target)
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/unittest/mock.py", line 1252, in _importer
    thing = _dot_lookup(thing, comp, import_path)
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/unittest/mock.py", line 1242, in _dot_lookup
    return getattr(thing, comp)
AttributeError: module 'multiprocessing' has no attribute 'shared_memory'

0:09:11 load avg: 0.71 [231/427/1] test_multiprocessing_forkserver -- test_multiprocessing_fork failed (1 error) in 1 min 11 sec
test test_multiprocessing_forkserver failed -- Traceback (most recent call last):
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/unittest/mock.py", line 1239, in _dot_lookup
    return getattr(thing, comp)
AttributeError: module 'multiprocessing' has no attribute 'shared_memory'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/test/_test_multiprocessing.py", line 3818, in test_shared_memory_basics
    with unittest.mock.patch(
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/unittest/mock.py", line 1422, in __enter__
    self.target = self.getter()
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/unittest/mock.py", line 1609, in <lambda>
    getter = lambda: _importer(target)
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/unittest/mock.py", line 1252, in _importer
    thing = _dot_lookup(thing, comp, import_path)
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/unittest/mock.py", line 1242, in _dot_lookup
    return getattr(thing, comp)
AttributeError: module 'multiprocessing' has no attribute 'shared_memory'

0:11:11 load avg: 0.93 [232/427/2] test_multiprocessing_main_handling -- test_multiprocessing_forkserver failed (1 error) in 2 min
0:11:18 load avg: 1.09 [233/427/2] test_multiprocessing_spawn
test test_multiprocessing_spawn failed -- Traceback (most recent call last):
  File "/tmp/tmpu30qfjpr/installation/lib/python3.10/unittest/mock.py", line 1239, in _dot_lookup
    return getattr(thing, comp)
AttributeError: module 'multiprocessing' has no attribute 'shared_memory'

I cannot reproduce it from installed Python or when testing directly on the repo, but the error seems to still happen from time to time.

[sobolevn]

Related issues:

• https://bugs.python.org/issue45042
• https://bugs.python.org/issue45052

[vstinner]

I guess that the test was previously skipped, and bpo-45042 enabled again the test:

commit e5976dd
Author: Miss Islington (bot) <31488909+miss-islington@users.noreply.github.com>
Date: Sat Sep 4 14:04:44 2021 -0700

bpo-45042: Now test classes decorated with `requires_hashdigest` are not skipped (GH-28060)


Co-authored-by: Serhiy Storchaka <storchaka@gmail.com>
(cherry picked from commit dd7b816ac87e468e2fa65ce83c2a03fe1da8503e)

Co-authored-by: Nikita Sobolev <mail@sobolevn.me>

[vstinner]

I'm not sure if unittest.mock code to import the module is reliable: see bpo-39551. It imports "multiprocessing", use getattr() to get multiprocessing.shared_memory. If getattr() fails with AttributeError, it tries to import "mulitprocessing.shared_memory", and then tries again the same getattr() on the previously imported "multiprocessing" module.

I'm curious if this change works around the issue:

diff --git a/Lib/unittest/mock.py b/Lib/unittest/mock.py
index c6067151de..1e3a8277ca 100644
--- a/Lib/unittest/mock.py
+++ b/Lib/unittest/mock.py
@@ -1238,7 +1238,7 @@ def _dot_lookup(thing, comp, import_path):
     try:
         return getattr(thing, comp)
     except AttributeError:
-        __import__(import_path)
+        thing = __import__(import_path)
         return getattr(thing, comp)

[kanavin]

I am seeing this one too in my yocto builds of 3.10rc2. What is bizarre is that the issue does not occur if the multiprocessing test is run in isolation:

python3 -m test -v test_multiprocessing_fork

but quite reliably does occur (three times in three different spots) if the whole test suite is executed:

python3 -m test -v

[pablogsal]

but quite reliably does occur (three times in three different spots) if the whole test suite is executed:

The thing is that we are running the test suite constantly on CI and buildbots and non of them have seen this problem :(

We should see if we could reproduce this easily first. Łukasz, could you take a look if you have some availability?

[vstinner]

The thing is that we are running the test suite constantly on CI and buildbots and non of them have seen this problem :(

Most (if not all) Python CIs run the Python test suite using -jN option which runs each test in isolation: a fresh process is spawned to a test file.

[vstinner]

Minimum command to reproduce the issue (on Linux):

$ ./python -m test -m test.test_logging.LogRecordTest.test_multiprocessing test_genericalias test_logging test_multiprocessing_fork -v

(...)
0:00:00 load avg: 0.45 Run tests sequentially
0:00:00 load avg: 0.45 [1/3] test_genericalias

----------------------------------------------------------------------
Ran 0 tests in 0.000s

OK
0:00:00 load avg: 0.49 [2/3] test_logging -- test_genericalias ran no tests
test_multiprocessing (test.test_logging.LogRecordTest) ... ok

----------------------------------------------------------------------
Ran 1 test in 0.008s

OK
0:00:00 load avg: 0.49 [3/3] test_multiprocessing_fork
test test_multiprocessing_fork crashed -- Traceback (most recent call last):
  File "/home/vstinner/python/main/Lib/test/libregrtest/runtest.py", line 340, in _runtest_inner
    refleak = _runtest_inner2(ns, test_name)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/vstinner/python/main/Lib/test/libregrtest/runtest.py", line 280, in _runtest_inner2
    the_module = importlib.import_module(abstest)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/vstinner/python/main/Lib/importlib/__init__.py", line 126, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "<frozen importlib._bootstrap>", line 1072, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1044, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1015, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 689, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 894, in exec_module
  File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
  File "/home/vstinner/python/main/Lib/test/test_multiprocessing_fork.py", line 2, in <module>
    import test._test_multiprocessing
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/vstinner/python/main/Lib/test/_test_multiprocessing.py", line 5374, in <module>
    class TestSyncManagerTypes(unittest.TestCase):
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/vstinner/python/main/Lib/test/_test_multiprocessing.py", line 5396, in TestSyncManagerTypes
    manager_class = multiprocessing.managers.SyncManager
                    ^^^^^^^^^^^^^^^^^^^^^^^^
AttributeError: module 'multiprocessing' has no attribute 'managers'

test_multiprocessing_fork failed (uncaught exception)
(...)

[vstinner]

I can still reproduce the issue if test_logging.py is simplified to:
---

import unittest
import sys

class LogRecordTest(unittest.TestCase):
    def test_multiprocessing(self):
        import multiprocessing.queues
        del sys.modules['multiprocessing']
        import multiprocessing

---

The "del sys.modules['multiprocessing']" line comes from LogRecordTest._extract_logrecord_process_name() method.