| msg300102 - (view) |
Author: STINNER Victor (vstinner) *  |
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) * |
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) * |
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) * |
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 (vstinner) * |
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 (vstinner) * |
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 (vstinner) * |
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 (vstinner) * |
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) |
|
|