deadlocks (Linux) (original) (raw)

Created on 2018-11-24 04:36 by Henrik Bengtsson, last changed 2022-04-11 14:59 by admin. This issue is now closed.

Messages (7)

msg330370 - (view)

Author: HenrikB (Henrik Bengtsson)

Date: 2018-11-24 04:36

(originally posted to https://mail.python.org/pipermail/python-list/2018-November/738209.html)

I ran into an interesting problem where calling 'subprocess.Popen(['/sbin/ldconfig', '-p'], stdin=PIPE)' hangs and never returns.

$ python Python 2.7.9 (default, Apr 23 2015, 22:07:47) [GCC 4.4.7 20120313 (Red Hat 4.4.7-11)] on linux2 Type "help", "copyright", "credits" or "license" for more information.

import subprocess p = subprocess.Popen(['/sbin/ldconfig', '-p'], stdout=subprocess.PIPE) ^CTraceback (most recent call last): File "", line 1, in File "/opt/Python/Python-2.7.9/lib/python2.7/subprocess.py", line 710, in init errread, errwrite) File "/opt/Python/Python-2.7.9/lib/python2.7/subprocess.py", line 1316, in _execute_child data = _eintr_retry_call(os.read, errpipe_read, 1048576) File "/opt/Python/Python-2.7.9/lib/python2.7/subprocess.py", line 476, in _eintr_retry_call return func(*args) KeyboardInterrupt

Note how I have to send a user interrupt to break out of 'subprocess.Popen()'.

TROUBLESHOOTING:

First, it's interesting to note that the following works:

import subprocess p = subprocess.Popen(['/sbin/ldconfig -p'], stdout=subprocess.PIPE, shell=True) out,err = p.communicate() len(out) 102460

which I believe is the same as:

import subprocess p = subprocess.Popen(['sh', '-c', '/sbin/ldconfig -p'], stdout=subprocess.PIPE) out,err = p.communicate() len(out) 102460

which also works.

Second, calling:

import subprocess p = subprocess.Popen(['/sbin/ldconfig', '-p']) 1562 libs found in cache `/etc/ld.so.cache' libzmq.so.1 (libc6,x86-64) => /usr/lib64/libzmq.so.1 libz.so.1 (libc6,x86-64) => /lib64/libz.so.1 [ ... all 102,460 bytes of ldconfig -p output ...] ld-linux-x86-64.so.2 (libc6,x86-64) => /lib64/ld-linux-x86-64.so.2

also works, so the PIPE is my main suspect.

Finally, if I do:

import subprocess p = subprocess.Popen(['/sbin/ldconfig', '-p'], stdout=subprocess.PIPE)

[ manually pkill -INT ldconfig' ]

out,err = p.communicate() len(out) 65536

then I notice that it reads exactly 65,536=2^16 bytes (out of 102,460 bytes). I suspect this is related to the default buffer-size limit of pipes set by the Linux kernel. Using strace on the latter Python process, reveals:

[...] open("/opt/Python/Python-2.7.9/lib/python2.7/lib-dynload/cStringIO.so", O_RDONLY) = 6 read(6, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@\32\0\0\0\0\0\0"..., 832) = 832 fstat(6, {st_mode=S_IFREG|0755, st_size=49556, ...}) = 0 mmap(NULL, 2115000, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 6, 0) = 0x2ad3ca6e7000 mprotect(0x2ad3ca6eb000, 2093056, PROT_NONE) = 0 mmap(0x2ad3ca8ea000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 6, 0x3000) = 0x2ad3ca8ea000 close(6) = 0 close(5) = 0 close(4) = 0 getrlimit(RLIMIT_NOFILE, {rlim_cur=641024, rlim_max=641024}) = 0 close(3) = 0 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ad3ca8ec000 write(1, "1\n", 21) = 2 pipe([3, 4]) = 0 fcntl(3, F_GETFD) = 0 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 fcntl(4, F_GETFD) = 0 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 pipe([5, 6]) = 0 fcntl(5, F_GETFD) = 0 fcntl(5, F_SETFD, FD_CLOEXEC) = 0 fcntl(6, F_GETFD) = 0 fcntl(6, F_SETFD, FD_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x2ad3c972adf0) = 239074 close(6) = 0 mmap(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ad3ca8ed000 read(5,

and 'strace' on the stalled 'ldconfig' process reveals:

$ strace -p $(pgrep ldconfig) Process 239074 attached - interrupt to quit write(1, "ibgconfmm-2.6.so.1 (libc6,x86-64"..., 4096 RH 6.6 0:- 1:-* 2:--

That latter 'write()' contains the bytes after position 65,536, i.e. bytes 65,537 and beyond (not shown, but verified after careful inspection).

MY CONCLUSION:

To me, this looks like a deadlock in Popen() itself - is that correct?

SESSION INFORMATION:

All of the above is with Python 2.7.9 (installed from EPEL), but I can also reproduce it with Python 2.7.15 installed from source.

What is also useful to know, is that I'm observing this on a legacy RHEL 6 system with a customized kernel part of the Scyld ClusterWare (https://www.penguincomputing.com/products/software/scyld-clusterware/) that cannot be updated:

$ uname -a Linux n6 2.6.32-504.12.2.el6.664g0000.x86_64 #1 SMP Wed Mar 11 14:20:51 EDT 2015 x86_64 x86_64 x86_64 GNU/Linux

I appreciate any suggestions to further troubleshoot this and ideally resolve it. The reason for this being an important issue is that 'find_library()' of ctypes.util performs the above stalling 'Popen(['/sbin/ldconfig', '-p'])' call that was introduced in Python (>= 2.7.13). This happens for instance whenever we try to create a new virtual environment using 'virtualenv'. In other words, the solution is not really to change the code to use, say, the shell=True approach.

msg330407 - (view)

Author: Inada Naoki (methane) * (Python committer)

Date: 2018-11-26 09:57

What is also useful to know, is that I'm observing this on a legacy RHEL 6 system with a customized kernel part of the Scyld ClusterWare (https://www.penguincomputing.com/products/software/scyld-clusterware/) that cannot be updated:

Do you mean this trouble is happened only on the system? Or can this trouble be reproducible on normal Linux kernel?

I think there are no bug in Python. See this part of your strace

pipe([5, 6])                            = 0
fcntl(5, F_GETFD)                       = 0
fcntl(5, F_SETFD, FD_CLOEXEC)           = 0
fcntl(6, F_GETFD)                       = 0
fcntl(6, F_SETFD, FD_CLOEXEC)           = 0
clone(child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x2ad3c972adf0) = 239074
close(6)                                = 0
mmap(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ad3ca8ed000
read(5,

Python creates pipe [5, 6], and set FD_CLOEXEC flag to them. When exec in child process succeeded, these FDs must be closed by Linux kernel.

Then, read(5, in parent process must not be blocked. It must return 0 soon. So I think there are some bug in your kernel, relating to CLOEXEC.

I am not interested in this issue much because 2.6.32 is too old to me and I never used "Scyld ClusterWare".

Maybe, you can consult with the company.

msg330409 - (view)

Author: STINNER Victor (vstinner) * (Python committer)

Date: 2018-11-26 10:12

Are you able to reproduce the issue with Python 3?

Can you please also try http://pypi.org/project/subprocess32/?

msg331004 - (view)

Author: HenrikB (Henrik Bengtsson)

Date: 2018-12-04 01:23

Thank you both for the comments and suggests. Before I'm getting to the "interesting" part, first to the "easy" one:

What is also useful to know, is that I'm observing this on a legacy RHEL 6 system with a customized kernel part of the Scyld ClusterWare (https://www.penguincomputing.com/products/software/scyld-clusterware/) that cannot be updated:

Do you mean this trouble is happened only on the system? Or can this trouble be reproducible on normal Linux kernel?

The issue only occurs on this particular setup and I have not seen it on the two other RHEL/Centos systems I have access to. More below.

Are you able to reproduce the issue with Python 3?

Yes, I can confirm that I'm seeing this issue also with Python 3.6.5 where:

import subprocess
p = subprocess.Popen(['/sbin/ldconfig', '-p'], stdout=subprocess.PIPE)

stalls.

Can you please also try http://pypi.org/project/subprocess32/?

Confirming that the following stalls on both Python 2.7.9 and 2.7.15:

import subprocess32
p = subprocess32.Popen(['/sbin/ldconfig', '-p'], stdout=subprocess32.PIPE)

POOR MAN'S DEBUGGING:

Some more narrowing down on exactly where in the code it get stuck, with the disclaimer that I'm kind of a rookie when it comes to Python so I don't really know how to debug interactively etc.

Using poor man's debug, that is, lots of print statements, I've narrowed down the stall of

import subprocess
p = subprocess.Popen(['/sbin/ldconfig', '-p'], stdout=subprocess.PIPE)

to occur in the call:

_execute_child(args = ['/sbin/ldconfig', '-p'], executable = None, preexec_fn = None, close_fds = False, cwd = None, env = None, universal_newlines = False, startupinfo = None, creationflags = 0, shell = False, to_close = set([3, 4]), p2cread = None, p2cwrite = None, c2pread = 3, c2pwrite = 4, errread = None, errwrite = None)

where the child process (self.pid == 0) get stuck while calling _dup2(c2pwrite = 4, 1) which in turn calls os.dup2(a = 4, b = 1). The parent process get stuck in the call data = _eintr_retry_call(os.read, errpipe_read, 1048576). Not sure if that rules out certain things, or it just confirms what is already known/what strace is already saying.

SOME MORE TROUBLESHOOTING:

So I think there are some bug in your kernel, relating to CLOEXEC.

I'm also leaning towards the issue is related to the kernel. What is really interesting is that executable '/sbin/ldconfig' does not exist:

$ ls /sbin/ldconfig
ls: cannot access /sbin/ldconfig: No such file or directory

but yet, I can call it:

$ /sbin/ldconfig -p | wc -c
102460

and the output is indeed valid(). For me, this strongly suggests that this particular system call is intercepted. I don't know the details, but I think this reflects the gist of the Scyld Clusterware kernel where it intercepts certain system calls makes a multi-node computer cluster to appear as one machine. () By valid I mean '/sbin/ldconfig -p' gives identical out on the compute nodes where this problem occurs as on the master node (where /sbin/ldconfig indeed exists) which Scyld is trying to "mirror" on the compute nodes. (I don't ask you to waste brain cycles on trying to follow this but I thought it's useful to put all this down for the record and potential future readers.)

Maybe, you can consult with the company.

I will try to reach out to them to have them confirm my troubleshooting and see if this has been fixed in a later release of theirs. (Unfortunately, it won't help our current legacy system, which we are slowly moving away. Regardless, by posting this here, I hope I'll spare at least one other person some troubleshooting if they find this post; it caused me and lots of other users 100's of hours of confusion and troubleshooting before we got this far.)

It would also be interesting to understand exactly what causes the stall. Is it indeed the pipe that gets filled up? Is that because the kernel does not respect the pipe limit and just dumps all output at once (> 65,536 bytes), i.e. it is a bug? Or is it that Python or one of its dependencies runs into a race condition because, say, it does not have a chance to set up the parent-child communication before the child (== the kernel) dumps too much data?

Inada Naoki, does the above new info give further evidence to your comment:

So I think there are some bug in your kernel, relating to CLOEXEC.

or did it possibly bring something new to the table? (I'm not too familiar with the Linux system calls and what to infer from strace logs).

A BROKEN DESIGN?

Finally, I don't know if the fact that /sbin/ldconfig does not exist but you can yet call it is (i) poorly designed kernel, or (ii) a valid design in the Unix world. I don't know the answer to this and I don't claim one is more correct than the other. I also don't know if there are other kernels out there that does this type of interception. If it is indeed a valid design, then one could argue that Python and other software tools should be able to handle it. FYI, this far I've/we've only hit this issue with Python (>= 2.7.13), maybe because of pure luck. It did not cause a problem in Python (< 2.7.13) and it does not cause a problem if we use subprocess.Popen(..., 'shell = True'). On the other hand, if one would argue that it is a poor design, then would it make sense to protect against by for instance asserting that the executable actually exists before calling it:

--- subprocess.py 2018-12-03 16:34:05.777608059 -0800 +++ subprocess.py.2.7.15 2018-12-03 16:33:21.124909394 -0800 @@ -918,9 +918,6 @@ if executable is None: executable = args[0]

       if not os.path.isfile(executable):

           raise RuntimeError("No such executable: " + executable)

        def _close_in_parent(fd):
            os.close(fd)
            to_close.remove(fd)

msg331014 - (view)

Author: Inada Naoki (methane) * (Python committer)

Date: 2018-12-04 08:01

where the child process (self.pid == 0) get stuck while calling _dup2(c2pwrite = 4, 1) which in turn calls os.dup2(a = 4, b = 1).

Doesn't child process get stuck while writing stdout?

It would also be interesting to understand exactly what causes the stall. Is it indeed the pipe that gets filled up? Is that because the kernel does not respect the pipe limit and just dumps all output at once (> 65,536 bytes), i.e. it is a bug? Or is it that Python or one of its dependencies runs into a race condition because, say, it does not have a chance to set up the parent-child communication before the child (== the kernel) dumps too much data?

In a normal case, when child process succeeded to exec, errpipe_write must be closed, by CLOEXEC flag. Then, parent process _eintr_retry_call(os.read, errpipe_read, 1048576) returns b"". So parent process can read from stdio pipes, and child process can write to stdio pipes more than 65536 bytes.

In your case, errpipe_write is not closed when exec is succeeded. That's kernel bug. Parent process _eintr_retry_call(os.read, errpipe_read, 1048576) does not return until child process exits. But child process is blocked when writing to stdout/err more than 65536 bytes. Deadlock happened.

A BROKEN DESIGN?

Finally, I don't know if the fact that /sbin/ldconfig does not exist but you can yet call it is (i) poorly designed kernel, or (ii) a valid design in the Unix world. I don't know the answer to this and I don't claim one is more correct than the other. I also don't know if there are other kernels out there that does this type of interception. If it is indeed a valid design, then one could argue that Python and other software tools should be able to handle it. FYI, this far I've/we've only hit this issue with Python (>= 2.7.13), maybe because of pure luck. It did not cause a problem in Python (< 2.7.13) and it does not cause a problem if we use subprocess.Popen(..., 'shell = True'). On the other hand, if one would argue that it is a poor design, then would it make sense to protect against by for instance asserting that the executable actually exists before calling it:

I don't know (i) or (II). But I don't think the assertion makes sense. I expect OSError rather than RuntimeError.

msg331027 - (view)

Author: STINNER Victor (vstinner) * (Python committer)

Date: 2018-12-04 10:34

I tested:

Python 2.6.6 (installed from RHEL) on RHEL6
Python 2.7.15 (compiled manually) on RHEL6
Python 2.7.15 (installed from Fedora) on Fedora 29

Note: I tested RHEL 6.10 with kernel 2.6.32-754.el6.x86_64.

The fact that Python 3 is also impacted makes me think that it's a bug in your kernel, not in Python.

"MY CONCLUSION: To me, this looks like a deadlock in Popen() itself - is that correct?"

It works on all systems except of yours, I don't think that it's a bug in Python.

You have to debug your kernel.

This issue is not a Python bug, so I close it.

If you are a Red Hat customer, contact Red Hat to get support.

msg331077 - (view)

Author: HenrikB (Henrik Bengtsson)

Date: 2018-12-04 20:58

Thanks for taking your time on this one.

I'll report back if I find out more about this kernel-specific issue.

Here're my replies to the outstanding questions/comments:

where the child process (self.pid == 0) get stuck while calling _dup2(c2pwrite = 4, 1) which in turn calls os.dup2(a = 4, b = 1).

Doesn't child process get stuck while writing stdout?

I'm not sure I understand; are you saying you would expect the child process to get stuck before reaching that line? If so, no, it's in the _dup2(c2pwrite = 4, 1) call where it (consistently) gets stuck.

But I don't think the assertion makes sense. I expect OSError rather than RuntimeError.

I only used RuntimeError here to keep it simple plus it wasn't obvious what the setup of OSError would be (I see that there is a FileNotFoundError in Python 3).

History

Date

User

Action

Args

2022-04-11 14:59:08

admin

set

github: 79486

2018-12-04 20:58:54

Henrik Bengtsson

set

messages: +

2018-12-04 10:34:37

vstinner

set

status: open -> closed
resolution: third party
messages: +

stage: resolved

2018-12-04 08:01:11

methane

set

messages: +

2018-12-04 01:24:00

Henrik Bengtsson

set

messages: +

2018-11-26 10:12:01

vstinner

set

messages: +

2018-11-26 10:11:33

vstinner

set

nosy: + vstinner

2018-11-26 09:57:36

methane

set

nosy: + methane
messages: +

2018-11-24 04:36:41

Henrik Bengtsson

create