distutils.spawn should use subprocess (hang in parallel builds on QNX)

@jaraco

BPO	39763
Nosy	@jaraco, @pitrou, @vstinner, @merwok, @dstufft, @aixtools
PRs	bpo-39763: distutils.spawn now uses subprocess #18743 bpo-39763: Refactor setup.py #18778 bpo-39763: Change test to check for `subprocess.check_output` during setup.py build phase #18847 bpo-39763: Add _bootsubprocess to build Python on AIX #18872
Files	fork_mt.py

^{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 = None
created_at = <Date 2020-02-26.19:18:35.569>
labels = ['3.8', 'library']
title = 'distutils.spawn should use subprocess (hang in parallel builds on QNX)'
updated_at = <Date 2020-07-04.01:26:37.758>
user = 'https://bugs.python.org/EladLahav'

bugs.python.org fields:

activity = <Date 2020-07-04.01:26:37.758>
actor = 'jaraco'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2020-02-26.19:18:35.569>
creator = 'Elad Lahav'
dependencies = []
files = ['48917']
hgrepos = []
issue_num = 39763
keywords = ['patch']
message_count = 36.0
messages = ['362717', '362728', '362731', '362732', '362743', '362752', '362794', '362818', '362822', '362824', '362826', '362847', '363017', '363038', '363058', '363165', '363172', '363173', '363176', '363349', '363363', '363646', '363711', '363749', '363754', '363780', '363782', '363784', '363840', '363841', '363853', '363855', '363943', '363945', '363947', '372974']
nosy_count = 7.0
nosy_names = ['jaraco', 'pitrou', 'vstinner', 'eric.araujo', 'dstufft', 'Michael.Felt', 'Elad Lahav']
pr_nums = ['18743', '18778', '18847', '18872']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = None
url = 'https://bugs.python.org/issue39763'
versions = ['Python 3.8']

The attached code causes the child processes to hang on QNX. The hang is caused by the logging module trying to acquire the module lock while in an atfork() handler. In a system where semaphore state is kept in user mode and is thus inherited from the parent on fork() the semaphore may appear to have a value of 0, and thus will never be posted to in the single-threaded child.
I don't know how it works on other systems - may be pure chance.

Note the original problem stems when you using "setup.py -j <NJOBS>".

The attached reproducer is a bit of a red herring, because indeed doing fork() + exec() in pure Python is too fragile. That is why the standard subprocess does it in C. The problem here is that the distutils.spawn module still has its hand-baked fork() + exec() pure Python code from the 1990s.

So the solution to the OP's actual problem should be to recode distutils.spawn using the subprocess module.

Original mailing-list discussion at:
https://mail.python.org/archives/list/python-dev@python.org/thread/PTJ3UAZNYBYBYQ4WLMSERZR2XIVWISLM/

I'm not convinced that a multi-threaded fork()+exec() from C would be any better, unless the Python code goes to great lengths to avoid any non-async-signal-safe operations between the fork() and the exec().
So along with the proposed change to switch to the subprocess() module I would like to propose that that module switch to using posix_spawn() instead of fork()+exec().

AttributeError: 'str' object has no attribute 'decode'

Oops, it should now be fixed by my second commit. Please retry PR 18872.

Comes further. The build finishes, but socket and asyncio are missing...

At least a build will proceed, and I can look into this new, perhaps unrelated issue re: socket later.

*** WARNING: renaming "_asyncio" since importing it failed: No module named '_socket'

New changeset addaaaa by Victor Stinner in branch 'master':
bpo-39763: Add _bootsubprocess to build Python on AIX (GH-18872)
addaaaa

At least a build will proceed, and I can look into this new, perhaps unrelated issue re: socket later.
*** WARNING: renaming "_asyncio" since importing it failed: No module named '_socket'

Do you see any error when the _socket module is built? Please open a new issue with full logs.

re: _socket - I'll start researching now, but it may still be related to this.

a) if it looks like related to this issue I'll add a some report here
b) in any case, as requested, I'll start a new issue - and leave it to you to decide to close that and continue here, or with the new issue.

OK. BEFORE I open a new issue, I am going to guess that something is wrong with finding _socket.so - because it exists, but "something" is not finding it.

Following modules built successfully but were removed because they could not be imported:^M
_asyncio ^M
^M
running build_scripts^M
copying and adjusting /data/prj/python/git/python3-3.9/Tools/scripts/pydoc3 -> build/scripts-3.9^M
copying and adjusting /data/prj/python/git/python3-3.9/Tools/scripts/idle3 -> build/scripts-3.9^M
copying and adjusting /data/prj/python/git/python3-3.9/Tools/scripts/2to3 -> build/scripts-3.9^M
changing mode of build/scripts-3.9/pydoc3 from 644 to 755^M
changing mode of build/scripts-3.9/idle3 from 644 to 755^M
changing mode of build/scripts-3.9/2to3 from 644 to 755^M
renaming build/scripts-3.9/pydoc3 to build/scripts-3.9/pydoc3.9^M
renaming build/scripts-3.9/idle3 to build/scripts-3.9/idle3.9^M
renaming build/scripts-3.9/2to3 to build/scripts-3.9/2to3-3.9^M
xlc_r -c -DNDEBUG -O -I/opt/include -O2 -qmaxmem=-1 -qarch=pwr5 -I../git/python3-3.9/Include/internal -IObjects -IInclude -IPython -I. -I../git/python3-3.9/Include -I/opt/include -DPy_BUILD_CORE -o Programs/_testembed.o ../git
/python3-3.9/Programs/_testembed.c^M
../git/python3-3.9/Modules/makexp_aix Modules/python.exp . libpython3.9.a; xlc_r /opt/lib/libintl.a -L/opt/lib -liconv -lexpat -Wl,-bE:Modules/python.exp -lld -o Programs/_testembed Programs/_testembed.o libpython3.9.so -lintl -l
dl -lm -lm ^M

NOTE: The module was built successfully, but not found.

root@x065:[/data/prj/python/python3-3.9]find . -name _socket.so
./build/lib.aix-5307-0747-32-3.9/_socket.so

I am confused.

The bot complains nearly immediately about missing _socket

Following modules built successfully but were removed because they could not be imported:
_asyncio                                                       
running build_scripts
copying and adjusting /home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Tools/scripts/pydoc3 -> build/scripts-3.9
copying and adjusting /home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Tools/scripts/idle3 -> build/scripts-3.9
copying and adjusting /home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Tools/scripts/2to3 -> build/scripts-3.9
changing mode of build/scripts-3.9/pydoc3 from 600 to 755
changing mode of build/scripts-3.9/idle3 from 600 to 755
changing mode of build/scripts-3.9/2to3 from 600 to 755
renaming build/scripts-3.9/pydoc3 to build/scripts-3.9/pydoc3.9
renaming build/scripts-3.9/idle3 to build/scripts-3.9/idle3.9
renaming build/scripts-3.9/2to3 to build/scripts-3.9/2to3-3.9
./python -E -c 'import sys ; from sysconfig import get_platform ; print("%s-%d.%d" % (get_platform(), *sys.version_info[:2]))' >platform
./python  ./Tools/scripts/run_tests.py -j 1 -u all -W --slowest --fail-env-changed --timeout=900 -j2 --junit-xml test-results.xml 
Traceback (most recent call last):
  File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/./Tools/scripts/run_tests.py", line 12, in <module>
    import test.support
  File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/test/support/__init__.py", line 6, in <module>
    import asyncio.events
  File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/asyncio/__init__.py", line 8, in <module>
    from .base_events import *
  File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/asyncio/base_events.py", line 23, in <module>
    import socket
  File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/socket.py", line 51, in <module>
    import _socket
ModuleNotFoundError: No module named '_socket'

while if I use my (now closed) pr18847 I do not get the results immediately - it starts the whole test series, and then fails - but not because _socket does not exist, instead:

0:00:48 [ 53/420/2] test_socket failed (30.4 sec) -- running: test_multiprocessing_fork (48.3 sec)
/data/prj/python/git/python3-3.9/Lib/test/test_socket.py:2557: RuntimeWarning: received malformed or improperly-truncated ancillary data
  result = sock.recvmsg(bufsize, *args)
/data/prj/python/git/python3-3.9/Lib/test/test_socket.py:2648: RuntimeWarning: received malformed or improperly-truncated ancillary data
  result = sock.recvmsg_into([buf], *args)
test test_socket failed -- Traceback (most recent call last):
  File "/data/prj/python/git/python3-3.9/Lib/test/test_socket.py", line 1481, in testGetaddrinfo
    self.assertEqual(socktype, socket.SOCK_STREAM)
AssertionError: 0 != <SocketKind.SOCK_STREAM: 1>

In short, stumped...

OK. BEFORE I open a new issue, I am going to guess that something is wrong with finding _socket.so - because it exists, but "something" is not finding it.

Did the build worked on AIX before the commit 1ec63b6 which changed distutils to use subprocess? Try commit dffe4c0 (parent of the other change).

This was already confirmed by both bots...

The last bot build that worked (and for both AIX bots) is: dffe4c0

The first build that failed (for both) is: 1ec63b6

See (pass) https://buildbot.python.org/all/#/builders/119/builds/383 and https://buildbot.python.org/all/#/builders/227/builds/369; fail https://buildbot.python.org/all/#/builders/119/builds/384
and https://buildbot.python.org/all/#/builders/227/builds/370

I'll checkout dffe4c0 to verify it still works successfully.

@exename

After a checkout the build finishes (successfully) with:
Python build finished successfully!
The necessary bits to build these optional modules were not found:
_gdbm _lzma _sqlite3
_tkinter _uuid readline
To find the necessary bits, look in setup.py in detect_modules() for the module's name.

The following modules found by detect_modules() in setup.py, have been
built by the Makefile instead, as configured by the Setup files:
_abc atexit pwd
time

running build_scripts
creating build/scripts-3.9
copying and adjusting /data/prj/python/git/python3-3.9/Tools/scripts/pydoc3 -> build/scripts-3.9
copying and adjusting /data/prj/python/git/python3-3.9/Tools/scripts/idle3 -> build/scripts-3.9
copying and adjusting /data/prj/python/git/python3-3.9/Tools/scripts/2to3 -> build/scripts-3.9
changing mode of build/scripts-3.9/pydoc3 from 644 to 755
changing mode of build/scripts-3.9/idle3 from 644 to 755
changing mode of build/scripts-3.9/2to3 from 644 to 755
renaming build/scripts-3.9/pydoc3 to build/scripts-3.9/pydoc3.9
renaming build/scripts-3.9/idle3 to build/scripts-3.9/idle3.9
renaming build/scripts-3.9/2to3 to build/scripts-3.9/2to3-3.9
/opt/bin/install -c -m 644 ../git/python3-3.9/Tools/gdb/libpython.py python-gdb.py
xlc_r -c -DNDEBUG -O -I/opt/include -O2 -qmaxmem=-1 -qarch=pwr5 -I/opt/include -O2 -qmaxmem=-1 -qarch=pwr5 -I../git/python3-3.9/Include/internal -IObjects -IInclude -IPython -I. -I../git/python3-3.9/Include -I/opt/include -I/op
t/include -DPy_BUILD_CORE -o Programs/_testembed.o ../git/python3-3.9/Programs/testembed.c
../git/python3-3.9/Modules/makexp_aix Modules/python.exp . libpython3.9.a; xlc_r /opt/lib/libintl.a -L/opt/lib -liconv -lexpat /opt/lib/libintl.a -L/opt/lib -liconv -lexpat -Wl,-bE:Modules/python.exp -lld -o Programs/_testembed
Programs/_testembed.o libpython3.9.a -lintl -ldl -lm -lm
sed -e "s,@exename@,/opt/bin/python3.9," < ../git/python3-3.9/Misc/python-config.in >python-config.py
LC_ALL=C sed -e 's,\$($[A-Za-z0-9]*$),\$\{\1\},g' < Misc/python-config.sh >python-config

root@x065:[/data/prj/python/python3-3.9]./python
Python 3.9.0a4+ (tags/v3.9.0a4-59-gdffe4c0709-dirty:dffe4c0709, Mar 11 2020, 17:09:06) [C] on aix
Type "help", "copyright", "credits" or "license" for more information.

>>

I created bpo-39936 "Python fails to build _asyncio on module on AIX" to debug the AIX build failure.

I've flagged bpo-41207 as a regression stemming from this effort.

The linked PRs and two follow-up issues have all been closed.

A

Navigation Menu

Repository navigation

distutils.spawn should use subprocess (hang in parallel builds on QNX) #83944

23 remaining items

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

distutils.spawn should use subprocess (hang in parallel builds on QNX) #83944

Description

Activity

EladLahav commented on Feb 26, 2020

pitrou commented on Feb 26, 2020

EladLahav commented on Feb 26, 2020

23 remaining items

vstinner commented on Mar 9, 2020

aixtools commented on Mar 9, 2020

vstinner commented on Mar 9, 2020

vstinner commented on Mar 9, 2020

aixtools commented on Mar 10, 2020

aixtools commented on Mar 10, 2020

aixtools commented on Mar 10, 2020

vstinner commented on Mar 10, 2020

aixtools commented on Mar 11, 2020

aixtools commented on Mar 11, 2020

vstinner commented on Mar 11, 2020

jaraco commented on Jul 4, 2020

AA-Turner commented on Jun 9, 2022

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions