classification
Title: subprocess's Popen closes stdout/stderr filedescriptors used in another thread when Popen errors
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.3, Python 3.4, Python 2.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: Jeong-Min.Lee, gregory.p.smith, janwijbrand, neologix, pitrou, python-dev
Priority: normal Keywords: patch

Created on 2013-08-27 12:06 by janwijbrand, last changed 2013-09-03 09:22 by janwijbrand. This issue is now closed.

Files
File name Uploaded Description Edit
subprocess_issue18851.patch pitrou, 2013-08-28 18:17
subprocess_issue18851_2.patch pitrou, 2013-08-28 20:29
subprocess_issue18851_3.patch pitrou, 2013-08-28 21:09
subprocess_issue18851_3.patch pitrou, 2013-08-29 17:56 review
Messages (16)
msg196276 - (view) Author: Jan-Wijbrand Kolman (janwijbrand) Date: 2013-08-27 12:06
An internal library that heavily uses subprocess.Popen() started failing its automated tests when we upgraded from Python 2.7.3 to Python 2.7.5. This library is used in a threaded environment. After debugging the issue, I was able to create a short Python script that demonstrates the error seen as in the failing tests.

This is the script (called "threadedsubprocess.py"):

===
import time
import threading
import subprocess

def subprocesscall():
    p = subprocess.Popen(
        ['ls', '-l'],
        stdin=subprocess.PIPE,
        stdout=subprocess.PIPE,
        stderr=subprocess.PIPE,
        )
    time.sleep(2) # simulate the Popen call takes some time to complete.
    out, err = p.communicate()
    print 'succeeding command in thread:', threading.current_thread().ident

def failingsubprocesscall():
    try:
        p = subprocess.Popen(
            ['thiscommandsurelydoesnotexist'],
            stdin=subprocess.PIPE,
            stdout=subprocess.PIPE,
            stderr=subprocess.PIPE,
            )
    except Exception as e:
        print 'failing command:', e, 'in thread:', threading.current_thread().ident

print 'main thread is:', threading.current_thread().ident

subprocesscall_thread = threading.Thread(target=subprocesscall)
subprocesscall_thread.start()
failingsubprocesscall()
subprocesscall_thread.join()
===

Note: this script does not exit with an IOError when ran from Python 2.7.3. It does fail at least 50% of the times when ran from Python 2.7.5 (both on the same Ubuntu 12.04 64-bit VM).

The error that is raised on Python 2.7.5 is this:

==
/opt/python/2.7.5/bin/python ./threadedsubprocess.py 
main thread is: 139899583563520
failing command: [Errno 2] No such file or directory 139899583563520
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/opt/python/2.7.5/lib/python2.7/threading.py", line 808, in __bootstrap_inner
    self.run()
  File "/opt/python/2.7.5/lib/python2.7/threading.py", line 761, in run
    self.__target(*self.__args, **self.__kwargs)
  File "./threadedsubprocess.py", line 13, in subprocesscall
    out, err = p.communicate()
  File "/opt/python/2.7.5/lib/python2.7/subprocess.py", line 806, in communicate
    return self._communicate(input)
  File "/opt/python/2.7.5/lib/python2.7/subprocess.py", line 1379, in _communicate
    self.stdin.close()
IOError: [Errno 9] Bad file descriptor

close failed in file object destructor:
IOError: [Errno 9] Bad file descriptor
==

When comparing the subprocess module from Python 2.7.3 to Python 2.7.5 I see the Popen()'s __init__() call indeed now explicitly closes the stdin, stdout and stderr file descriptors in case executing the command somehow fails. This seems to be an intended fix applied in Python 2.7.4 to prevent leaking file descriptors (http://hg.python.org/cpython/file/ab05e7dd2788/Misc/NEWS#l629).

The diff between Python 2.7.3 and Python 2.7.5 that seems to be relevant to this issue is in the Popen __init__():

==
@@ -671,12 +702,33 @@
          c2pread, c2pwrite,
          errread, errwrite) = self._get_handles(stdin, stdout, stderr)

-        self._execute_child(args, executable, preexec_fn, close_fds,
-                            cwd, env, universal_newlines,
-                            startupinfo, creationflags, shell,
-                            p2cread, p2cwrite,
-                            c2pread, c2pwrite,
-                            errread, errwrite)
+        try:
+            self._execute_child(args, executable, preexec_fn, close_fds,
+                                cwd, env, universal_newlines,
+                                startupinfo, creationflags, shell,
+                                p2cread, p2cwrite,
+                                c2pread, c2pwrite,
+                                errread, errwrite)
+        except Exception:
+            # Preserve original exception in case os.close raises.
+            exc_type, exc_value, exc_trace = sys.exc_info()
+
+            to_close = []
+            # Only close the pipes we created.
+            if stdin == PIPE:
+                to_close.extend((p2cread, p2cwrite))
+            if stdout == PIPE:
+                to_close.extend((c2pread, c2pwrite))
+            if stderr == PIPE:
+                to_close.extend((errread, errwrite))
+
+            for fd in to_close:
+                try:
+                    os.close(fd)
+                except EnvironmentError:
==

Note: I think to see a similar change in the subprocess.Popen() __init__() from Python-3.3.0 to Python-3.3.1.
msg196393 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2013-08-28 17:50
Yes, the problem is that the pipes FDs are closed twice if fork() succeeds, but exec() fails.

They're closed in _execute_child():
  1286                 if p2cread is not None and p2cwrite is not None:
  1287                     os.close(p2cread)
  1288                 if c2pwrite is not None and c2pread is not None:
  1289                     os.close(c2pwrite)
  1290                 if errwrite is not None and errread is not None:
  1291                     os.close(errwrite)

And then again in Popen.__init__:
   716             if stdin == PIPE:
   717                 to_close.extend((p2cread, p2cwrite))
   718             if stdout == PIPE:
   719                 to_close.extend((c2pread, c2pwrite))
   720             if stderr == PIPE:
   721                 to_close.extend((errread, errwrite))
msg196396 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-08-28 18:09
I wonder how the closing works under Windows. os.close() is called on handles returned by _get_handles(), but those are Windowns HANDLE values, not C file descriptors: os.close() probably fails on them (don't have a Windows VM to check, sorry). I guess the HANDLEs are then leaked...
msg196397 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-08-28 18:17
Here is a patch for 2.7. I don't know how to write a test for it, though.
msg196416 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-08-28 20:29
Ok, here is a fixed patch for Windows under 2.7.
msg196422 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-08-28 21:09
Updated patch with test.
msg196443 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2013-08-29 07:13
fyi - i am unable to reproduce this when using subprocess32 instead of subprocess.  https://pypi.python.org/pypi/subprocess32

That is what i recommend _anyone_ using Python 2.x use instead.

Regardless if this was reintroduced in 2.7.5 we need to re-fix it.

i haven't tested 3.2 or 3.3 or default yet (given the backport isn't showing the problem i'm hoping they don't either but they need testing).
msg196448 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-08-29 09:04
Gregory, it seems fixed indeed under Unix but I'm not sure about Windows. Read what I wrote above: apparently the cleanup code calls os.close() on a Windows HANDLE; then conveniently it swallows the exception :-)

Also, the Windows version of _execute_child doesn't set _closed_child_pipe_fds.
msg196449 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-08-29 09:04
(in any case, the test is probably worth adding)
msg196463 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2013-08-29 17:04
Rietveld's choking on git diffs.
msg196471 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-08-29 17:53
Ha, sorry. Here is a non-git patch.
msg196472 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-08-29 17:56
Sorry, wrong patch. Uploading again.
msg196582 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2013-08-30 21:45
New changeset 43749cb6bdbd by Antoine Pitrou in branch '2.7':
Issue #18851: Avoid a double close of subprocess pipes when the child process fails starting.
http://hg.python.org/cpython/rev/43749cb6bdbd
msg196586 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2013-08-30 22:12
New changeset c11754defe1c by Antoine Pitrou in branch '3.3':
Forward port new tests from Issue #18851.
http://hg.python.org/cpython/rev/c11754defe1c

New changeset 290ca31d4cfe by Antoine Pitrou in branch 'default':
Forward port new tests from Issue #18851.
http://hg.python.org/cpython/rev/290ca31d4cfe
msg196588 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-08-30 22:13
Committed after applying Charles-François's suggested fixes. Thanks!
msg196831 - (view) Author: Jan-Wijbrand Kolman (janwijbrand) Date: 2013-09-03 09:22
Thanks you for the swift followup!
History
Date User Action Args
2013-09-03 09:22:31janwijbrandsetmessages: + msg196831
2013-08-30 22:13:48pitrousetstatus: open -> closed
resolution: fixed
messages: + msg196588

stage: resolved
2013-08-30 22:12:48python-devsetmessages: + msg196586
2013-08-30 21:45:58python-devsetnosy: + python-dev
messages: + msg196582
2013-08-29 17:56:23pitrousetfiles: + subprocess_issue18851_3.patch

messages: + msg196472
2013-08-29 17:56:00pitrousetfiles: - subprocess_issue18851_3.patch
2013-08-29 17:53:18pitrousetfiles: + subprocess_issue18851_3.patch

messages: + msg196471
2013-08-29 17:04:18neologixsetmessages: + msg196463
2013-08-29 09:04:54pitrousetmessages: + msg196449
2013-08-29 09:04:33pitrousetmessages: + msg196448
2013-08-29 07:13:01gregory.p.smithsetmessages: + msg196443
2013-08-28 21:09:36pitrousetfiles: + subprocess_issue18851_3.patch

messages: + msg196422
2013-08-28 20:29:23pitrousetfiles: + subprocess_issue18851_2.patch

messages: + msg196416
2013-08-28 18:17:35pitrousetfiles: + subprocess_issue18851.patch
keywords: + patch
messages: + msg196397
2013-08-28 18:09:28pitrousetmessages: + msg196396
2013-08-28 17:50:16neologixsetnosy: + neologix
messages: + msg196393
2013-08-28 07:35:42Jeong-Min.Leesetnosy: + Jeong-Min.Lee
2013-08-27 13:01:36r.david.murraysetnosy: + gregory.p.smith, pitrou

versions: + Python 3.4
2013-08-27 12:06:55janwijbrandcreate