classification
Title: [EASY] subprocess: TypeError: can't concat str to bytes, in _execute_child()
Type: Stage: resolved
Components: Library (Lib) Versions: Python 3.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: gregory.p.smith Nosy List: ammar2, gregory.p.smith, haypo
Priority: normal Keywords: easy, patch

Created on 2017-08-10 15:29 by haypo, last changed 2017-10-09 15:55 by haypo. This issue is now closed.

Files
File name Uploaded Description Edit
subprocess_bug.patch haypo, 2017-08-10 15:29
Pull Requests
URL Status Linked Edit
PR 3066 merged ammar2, 2017-08-10 19:17
PR 3388 merged gregory.p.smith, 2017-09-06 17:48
PR 3896 merged haypo, 2017-10-05 13:08
PR 3897 open python-dev, 2017-10-05 13:34
Messages (9)
msg300102 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-10 15:29
Lib/subprocess.py contains the following code:

                try:
                    exception_name, hex_errno, err_msg = (
                            errpipe_data.split(b':', 2))
                except ValueError:
                    exception_name = b'SubprocessError'
                    hex_errno = b'0'
                    err_msg = (b'Bad exception data from child: ' +
                               repr(errpipe_data))

b'...' + repr() is wrong: it raises a "TypeError: can't concat str to bytes" when python3 is run with -bb.


Example with attached subprocess_bug.patch:

haypo@selma$ ./python -bb -m test -v test_subprocess -m test_invalid_args
(...)
======================================================================
ERROR: test_invalid_args (test.test_subprocess.ContextManagerTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/haypo/prog/python/master/Lib/subprocess.py", line 1309, in _execute_child
    errpipe_data.split(b':', 1))
ValueError: not enough values to unpack (expected 3, got 2)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/haypo/prog/python/master/Lib/test/test_subprocess.py", line 2880, in test_invalid_args
    stderr=subprocess.PIPE) as proc:
  File "/home/haypo/prog/python/master/Lib/subprocess.py", line 709, in __init__
    restore_signals, start_new_session)
  File "/home/haypo/prog/python/master/Lib/subprocess.py", line 1314, in _execute_child
    repr(errpipe_data))
TypeError: can't concat str to bytes


IMHO err_msg should be decoded using err_msg.decode(errors="surrogatepass") and then use 'Bad ...: %s' % err_msg. It would need to add an "else:" block to the try/except to do the err_msg.decode(errors="surrogatepass") when no error is raised. Well, something like that :-)
msg301447 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2017-09-06 06:41
New changeset 3fc499bca18454b9f432b9b0106cab662bfeb549 by Gregory P. Smith (Ammar Askar) in branch 'master':
bpo-31178: Avoid concatenating bytes with str in subprocess error (#3066)
https://github.com/python/cpython/commit/3fc499bca18454b9f432b9b0106cab662bfeb549
msg301448 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2017-09-06 06:45
awaiting our new carrot nosed bot the create the backport PR to take care of 3.6 :)
msg301450 - (view) Author: Ammar Askar (ammar2) * Date: 2017-09-06 06:58
If it doesn't manage to make it by tomorrow afternoon, I can backport it manually. It doesn't look like its been able to do it yet.
msg301515 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2017-09-06 20:34
New changeset 3bad1650a03fdc8cfdd4cce154e1b2c07e3e4fa0 by Gregory P. Smith in branch '3.6':
[3.6] bpo-31178: Avoid concatenating bytes with str in subprocess error (GH-3066) (#3388)
https://github.com/python/cpython/commit/3bad1650a03fdc8cfdd4cce154e1b2c07e3e4fa0
msg303762 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-05 13:12
A colleague packaging Python for Red Hat Entreprise Linux reported me that tests hang randomly on test_exception_errpipe_bad_data() of test_subprocess. I don't know why exactly, but using strace, I noticed that the "unit test" calls os.waitpid() with the pid returned by the mocked fork_exec(): pid 0. So the test calls os.waitpid(0, 0).

In a REPL on my Fedora 26, os.waitpid(0, 0) raises "ChildProcessError: [Errno 10] No child processes". I'm not sure that waitpid() is the cause of the hang, but it doesn't seem correct to me to call waitpid() with the result of a mock function, since the mock doesn't create a real child process.

Attached PR 3896 mocks also os.waitpid() to fix this bug. I reopen the issue to discuss this bug in the new test added in this issue.
msg303763 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-05 13:31
> In a REPL on my Fedora 26, os.waitpid(0, 0) raises "ChildProcessError: [Errno 10] No child processes". I'm not sure that waitpid() is the cause of the hang, (...)

Oh wait, now I understood the full picture.

Summary:

* 2 new tests were added to test_subprocess and these tests call waitpid(0, 0) by mistake
* In general, waitpid(0, 0) returns immediately and the code handles it properly
* Sometimes, a previous test leaks a child process and so waitpid(0, 0) takes a few seconds or can even block

--

Running tests leak randomly child processes. See for example my recent test_socketserver fix in Python 3.6: commit fdcf3e9629201ef725af629d99e02215a2d657c8. This commit is *not* part of the recent Python 3.6.3 release, tested by my colleague.

This fix is for the bug bpo-31593: test_socketserver leaked *randomly* child processes. Depending on the system load, waitpid() was called or not called to read the child process exit status.

If you run "./python -m test test_socketserver test_subprocess" and test_socketserver() doesn't call waitpid() on a single process, it's possible that test_subprocess hangs on waitpid(0, 0): waiting on the process spawned by test_socketserver.

test_socketserver is just one example, I fixed many other bugs in the Python test suite. Running Python tests in subprocesses using "./python -m test -jN ...", at least -j1, reduces the effect of the bug.

Short script to explain the bug:
---
import subprocess, sys, os, time

args = [sys.executable, '-c', 'import time; time.sleep(2)']
proc = subprocess.Popen(args)
t0 = time.monotonic()
print("waitpid(0, 0)...")
pid, status = os.waitpid(0, 0)
dt = time.monotonic() - t0
print("%.1f sec later: waitpid(0, 0) -> %s" % (dt, (pid, status)))
proc.wait()
---

This script takes 3 seconds, since a test leaked a child process which takes time to complete.
msg303764 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-05 13:32
New changeset 11045c9d8a21dd9bd182a3939189db02815f9783 by Victor Stinner in branch 'master':
bpo-31178: Mock os.waitpid() in test_subprocess (#3896)
https://github.com/python/cpython/commit/11045c9d8a21dd9bd182a3939189db02815f9783
msg303980 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-09 15:54
commit fae0512e58619231a566bf77aa21148440b0ec8d
Author: Miss Islington (bot) <31488909+miss-islington@users.noreply.github.com>
Date:   Thu Oct 5 07:10:59 2017 -0700

    [3.6] bpo-31178: Mock os.waitpid() in test_subprocess (GH-3896) (#3897)
    
    Fix test_exception_errpipe_bad_data() and
    test_exception_errpipe_normal() of test_subprocess: mock os.waitpid()
    to avoid calling the real os.waitpid(0, 0) which is an unexpected
    side effect of the test.
    (cherry picked from commit 11045c9d8a21dd9bd182a3939189db02815f9783)
History
Date User Action Args
2017-10-09 15:55:17hayposetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2017-10-09 15:54:52hayposetmessages: + msg303980
2017-10-05 13:34:39python-devsetstage: resolved -> patch review
pull_requests: + pull_request3868
2017-10-05 13:32:55hayposetmessages: + msg303764
2017-10-05 13:31:34hayposetmessages: + msg303763
2017-10-05 13:12:25hayposetstatus: closed -> open
resolution: fixed -> (no value)
messages: + msg303762
2017-10-05 13:08:52hayposetpull_requests: + pull_request3867
2017-09-06 20:36:45gregory.p.smithsetstatus: open -> closed
resolution: fixed
stage: resolved
2017-09-06 20:34:19gregory.p.smithsetmessages: + msg301515
2017-09-06 17:48:24gregory.p.smithsetpull_requests: + pull_request3395
2017-09-06 06:58:31ammar2setnosy: + ammar2
messages: + msg301450
2017-09-06 06:45:59gregory.p.smithsetassignee: gregory.p.smith
messages: + msg301448
versions: + Python 3.6, - Python 3.7
2017-09-06 06:41:32gregory.p.smithsetnosy: + gregory.p.smith
messages: + msg301447
2017-08-10 19:17:41ammar2setpull_requests: + pull_request3103
2017-08-10 15:29:44haypocreate