Messages (4) msg233788 - (view) Author: Thomas D. (whissi) Date: 2015-01-10 00:02

Hi,

to demonstrate the problem you need >=systemd-217:

# python3.4
Python 3.4.2 (default, Oct 12 2014, 20:09:43)
[GCC 4.8.3] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import subprocess
>>> sp = subprocess.Popen(["/sbin/udevd", "--daemon"], stdout=subprocess.PIPE, stderr=subprocess.PIPE)
>>> out, err = sp.communicate()

[hangs]

"ps" will show

root       9619  0.0  0.1  23340  5404 pts/5    Ss   Jan09   0:00  \_ -bash
root      13291  0.0  0.2  45352  9784 pts/5    S+   00:34   0:00      \_ python3.4
root      13311  0.0  0.0      0     0 pts/5    Z+   00:34   0:00          \_ [udevd] <defunct>

Calling "/sbin/udevd --daemon" from the shell works fine.

>>> errorlog = open("/tmp/stderr.log", "wb")
>>> sp = subprocess.Popen(["/sbin/udevd", "--daemon"], stdout=subprocess.PIPE, stderr=errorlog)

works, too.

The problem first appeared in systemd-217. I bisected systemd's source code and the commit since when Python's subprocess module is unable to start udevd is

https://github.com/systemd/systemd/commit/5c67cf2774a8b964f4d7cd92a4c447da81ac6087


This is not a systemd/udev only problem. The problem was first seen with the php-fpm daemon from PHP (but only when using "error_log = syslog").

Please see the original bug report at https://github.com/saltstack/salt/issues/14957 for more details.

Because Salt is still at Python 2.7, the problem can be reproduced with Python 2.7, too.


Is it a bug in subprocess? In systemd/PHP? Are we (salt) using subprocess the wrong way?

Thanks!


PS:
On your system, "/sbin/udevd" will be probably "/lib/systemd/systemd-udevd"

Not sure if this is related to http://bugs.python.org/issue12786 in some ways.

msg233797 - (view) Author: Martin Panter (martin.panter) * Date: 2015-01-10 03:05

I suspect this is not a bug but a misunderstanding of how communiate(), pipes, daemon processes, etc, work. If communicate() didn’t wait for stderr to be closed, then how would it know it had read all the data that was written into the pipe?

I don’t have that version of “systemd”, but I guess your daemon leaves its output pipes open and continues to run in the background, so communicate() is waiting in case the daemon writes anything to the pipes. This would demonstrate the same situation using a Python subprocess:

import subprocess
import sys
script = """import os, time
if not os.fork():  # Child process
    time.sleep(30)
    print("Finally!")
"""
args = (sys.executable, "-c", script)
proc = subprocess.Popen(args, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
proc.communicate()
# Hangs for 30 s and then returns (b'Finally!\n', b'')

If you want communicate() to return as soon as a daemon forks into the background, don’t read from the daemon’s output pipes. If you want to read data that the foreground process writes and ignore any data that the background process might write to the same pipes, that’s asking for race conditions.

msg265180 - (view) Author: Martin Panter (martin.panter) * Date: 2016-05-09 03:44

I suggest closing this. Depending on what the daemons are supposed to do, I think this is either a bug with “systemd” and PHP holding onto stderr when they become daemons, or a bug/misunderstanding with how Thomas was using the subprocess module and communicate().

msg265187 - (view) Author: Thomas D. (whissi) Date: 2016-05-09 09:42

Yep, I agree with you. This can be closed.

Thanks to your clarification the problem could be resolved upstream.

The udev problem was resolved in https://github.com/systemd/systemd/issues/190 and the PHP problem has a pending PR https://github.com/php/php-src/pull/1432

History Date User Action Args 2022-04-11 14:58:11adminsetgithub: 67402 2016-05-09 09:42:28whissisetstatus: pending -> closed

messages: + msg265187

2016-05-09 03:44:05martin.pantersetstatus: open -> pending
resolution: third party
messages: + msg265180
2015-01-10 03:05:50martin.pantersetnosy: + martin.panter
messages: + msg233797
2015-01-10 00:02:11whissicreate