classification
Title: test_multiprocessing_fork fails if run sequentially after test_genericalias and test_logging
Type: Stage: resolved
Components: Tests Versions: Python 3.10
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: Alexander Kanavin, lukasz.langa, miss-islington, pablogsal, sobolevn, vstinner
Priority: normal Keywords: patch

Created on 2021-09-07 14:33 by pablogsal, last changed 2021-10-04 19:18 by pablogsal. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 28387 merged sobolevn, 2021-09-16 14:26
PR 28462 merged miss-islington, 2021-09-19 22:50
Messages (15)
msg401287 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2021-09-07 14:33
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.
msg401291 - (view) Author: Nikita Sobolev (sobolevn) * Date: 2021-09-07 14:37
Related issues:
- https://bugs.python.org/issue45042
- https://bugs.python.org/issue45052
msg401332 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-09-07 19:22
I guess that the test was previously skipped, and bpo-45042 enabled again the test:

commit e5976dd2e6e966183da59df99978ebcb4b3a32df
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>
msg401333 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-09-07 19:25
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)
msg401846 - (view) Author: Alexander Kanavin (Alexander Kanavin) Date: 2021-09-15 16:12
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
msg401855 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2021-09-15 16:47
> 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?
msg401925 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-09-16 07:42
> 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.
msg401928 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-09-16 08:17
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)
(...)
msg401929 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-09-16 08:26
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.
msg401930 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-09-16 08:29
> ./python -m test -m test.test_logging.LogRecordTest.test_multiprocessing test_genericalias test_logging test_multiprocessing_fork -v

This command reproduces the issue:

* importing test.test_genericalias imports multiprocessing submodules like multiprocessing.queues
* test_logging does: del sys.modules['multiprocessing']
* test_multiprocessing_fork fails to import multiprocessing submodules
msg401931 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-09-16 08:35
The issue can be reproduced just with these lines:
---
import sys
import multiprocessing.queues
del sys.modules['multiprocessing']
import multiprocessing
import multiprocessing.connection
from multiprocessing.connection import wait
connection = multiprocessing.connection   # AttributeError here
---
msg402178 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2021-09-19 22:50
New changeset 1d42408495402b06ecae91420735aeff454be6b5 by Nikita Sobolev in branch 'main':
bpo-45128: fixes `test_multiprocessing_fork` mysterious crash (GH-28387)
https://github.com/python/cpython/commit/1d42408495402b06ecae91420735aeff454be6b5
msg402183 - (view) Author: miss-islington (miss-islington) Date: 2021-09-19 23:13
New changeset 0e9608680525b120fc8eaad9f1cb2f729a6c22ae by Miss Islington (bot) in branch '3.10':
bpo-45128: fixes `test_multiprocessing_fork` mysterious crash (GH-28387)
https://github.com/python/cpython/commit/0e9608680525b120fc8eaad9f1cb2f729a6c22ae
msg402199 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-09-20 07:16
This bug was interesting (funny) :-) Thanks for the fix Nikita Sobolev :-)
msg403165 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2021-10-04 19:18
New changeset 76611038bc3d2aa643dce45448f5c7044dd4fd06 by Pablo Galindo (Miss Islington (bot)) in branch '3.10':
bpo-45128: fixes `test_multiprocessing_fork` mysterious crash (GH-28387)
https://github.com/python/cpython/commit/76611038bc3d2aa643dce45448f5c7044dd4fd06
History
Date User Action Args
2021-10-04 19:18:43pablogsalsetmessages: + msg403165
2021-09-20 07:16:19vstinnersetmessages: + msg402199
2021-09-19 23:34:08pablogsalsetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2021-09-19 23:13:11miss-islingtonsetmessages: + msg402183
2021-09-19 22:50:36miss-islingtonsetnosy: + miss-islington
pull_requests: + pull_request26863
2021-09-19 22:50:12pablogsalsetmessages: + msg402178
2021-09-16 14:26:31sobolevnsetkeywords: + patch
stage: patch review
pull_requests: + pull_request26800
2021-09-16 08:36:50vstinnersettitle: test_multiprocessing_fork fails if run sequentially after test_logging -> test_multiprocessing_fork fails if run sequentially after test_genericalias and test_logging
2021-09-16 08:35:21vstinnersetmessages: + msg401931
2021-09-16 08:29:07vstinnersetmessages: + msg401930
2021-09-16 08:27:15vstinnersettitle: test_multiprocessing fails sporadically on the release artifacts -> test_multiprocessing_fork fails if run sequentially after test_logging
2021-09-16 08:26:27vstinnersetmessages: + msg401929
2021-09-16 08:17:26vstinnersetmessages: + msg401928
2021-09-16 07:42:04vstinnersetmessages: + msg401925
2021-09-15 16:47:55pablogsalsetnosy: + lukasz.langa
messages: + msg401855
2021-09-15 16:12:05Alexander Kanavinsetnosy: + Alexander Kanavin
messages: + msg401846
2021-09-07 19:25:37vstinnersetmessages: + msg401333
2021-09-07 19:22:15vstinnersetnosy: + vstinner
messages: + msg401332
2021-09-07 14:37:24sobolevnsetnosy: + sobolevn
messages: + msg401291
2021-09-07 14:33:53pablogsalcreate