Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

subprocess: Popen.kill() + Popen.communicate() is blocking until all processes using the pipe close the pipe #82388

Closed
vstinner opened this issue Sep 17, 2019 · 10 comments
Labels
3.9 only security fixes stdlib Python modules in the Lib dir

Comments

@vstinner
Copy link
Member

BPO 38207
Nosy @vstinner, @jkloth, @miss-islington
PRs
  • bpo-37531: regrtest ignores output on timeout #16659
  • [3.8] bpo-37531: regrtest ignores output on timeout (GH-16659) #16676
  • [3.7] bpo-37531: regrtest ignores output on timeout (GH-16659) #16677
  • Files
  • communicate_close.py
  • Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.

    Show more details

    GitHub fields:

    assignee = None
    closed_at = <Date 2020-02-07.10:48:47.697>
    created_at = <Date 2019-09-17.23:30:48.162>
    labels = ['library', '3.9']
    title = 'subprocess: Popen.kill() + Popen.communicate() is blocking until all processes using the pipe close the pipe'
    updated_at = <Date 2020-02-07.10:48:47.697>
    user = 'https://github.com/vstinner'

    bugs.python.org fields:

    activity = <Date 2020-02-07.10:48:47.697>
    actor = 'vstinner'
    assignee = 'none'
    closed = True
    closed_date = <Date 2020-02-07.10:48:47.697>
    closer = 'vstinner'
    components = ['Library (Lib)']
    creation = <Date 2019-09-17.23:30:48.162>
    creator = 'vstinner'
    dependencies = []
    files = ['48612']
    hgrepos = []
    issue_num = 38207
    keywords = ['patch']
    message_count = 10.0
    messages = ['352673', '352678', '352729', '354222', '354269', '354271', '354278', '354820', '354823', '361565']
    nosy_count = 3.0
    nosy_names = ['vstinner', 'jkloth', 'miss-islington']
    pr_nums = ['16659', '16676', '16677']
    priority = 'normal'
    resolution = 'fixed'
    stage = 'resolved'
    status = 'closed'
    superseder = None
    type = None
    url = 'https://bugs.python.org/issue38207'
    versions = ['Python 3.9']

    @vstinner
    Copy link
    Member Author

    On Windows, the communicate() method of subprocess.Popen is implemented with threads calling:

    def _readerthread(self, fh, buffer):
        buffer.append(fh.read())
        fh.close()

    where fh is one the Popen pipes: popen.stdout or popen.stderr.

    For stdout=PIPE and/or stderr=PIPE, Popen._get_handles() creates a pipe with _winapi.CreatePipe(None, 0).

    The fh.read() calls only completes when the write end of the pipe is closed: when all open handles of the write end of the pipe are closed.

    When using Popen(stdout=PIPE), Python uses the pipe as stdout:

                startupinfo.dwFlags |= _winapi.STARTF_USESTDHANDLES
                startupinfo.hStdInput = p2cread
                startupinfo.hStdOutput = c2pwrite
                startupinfo.hStdError = errwrite
    

    So far so good, it works well when Python spawns a single process.

    --

    Problems arise when the child process itself spawns new processes. In that case, the stdout pipe is inherited by other processes.

    Popen.communicate() will block until all processes close the pipe.

    This behavior is surprising for the following pattern:
    ------------------
    try:
    stdout, stderr = popen.communicate(timeout=5.0)
    except subprocess.TimeoutExpired:
    popen.kill()
    stdout, stderr = popen.communicate()
    ------------------

    I would expect that the second communicate() call completes immediately since we just killed the process: Windows knows that child process is dead, Python knows that Popen object has been kill, but fh.read() continues to block (until all processes closed the pipe).

    I would expect communicate() to complete immediately.

    The problem is that fh.read() only returns once all data is returned at once. If fh.read() call is cancelled somehow, communicate() would just return empty data: we loose all data.

    --

    Eryk Sun proposed two solutions:
    https://bugs.python.org/issue37531#msg350246

    "For Windows, subprocess could have a _read_all(file) method that special cases a pipe. The read loop for a pipe would check whether the child has exited. Then call _winapi.PeekNamedPipe on the handle (from get_osfhandle), and do a raw read of the available bytes. If the child has exited or PeekNamedPipe fails (EPIPE), then break, join the partial reads, decode and translate newlines if it's text mode, and return."

    and:
    https://bugs.python.org/issue37531#msg350329

    "Alternatively, instead of special casing the file type and spinning on PeekNamedPipe, the workaround could be based on a multiple-object wait that includes the child process handle. In this case, communicate() would always call _communicate in Windows, regardless of the timeout or number of pipes -- because simplistically calling either self.stdout.read() or self.stderr.read() could hang.

    The implementation would be moderately complicated. If we stop waiting on the reader threads because the process exited, we can give the threads a short time to finish reading and close the files -- maybe 250 ms is enough. But if they haven't exited at this time, we can't simply raise a TimeoutExpired exception if the call hasn't actually timed out. To finish the _communicate call, we would have to cancel the pending reads and join() the threads.

    We can force a reader thread to exit by canceling the read via WINAPI CancelIoEx. However, _readerthread has to be modified to support this. It could be implemented as a loop that calls _winapi.ReadFile to read the output in chunks that get appended to the buffer list. The read loop would break for either ERROR_BROKEN_PIPE or ERROR_OPERATION_ABORTED (canceled).

    The final step in _communicate would be to concatenate the partial reads. If it's text mode, it would also have to decode the bytes and translate newlines. The POSIX implementation of _communicate has to do this, so we already have a _translate_newlines method for this case.

    Note that _winapi.WaitForMultipleObjects is interruptible in the main thread via Ctrl+C, which is a bonus improvement since Thread.join() can't be interrupted in Windows."

    --

    This issue has been discussed in bpo-37531 about regrtest:

    https://bugs.python.org/issue37531#msg350181

    It impacts the Python test suite when a test uses multiprocessing (for example) which spawns new processes.

    @vstinner vstinner added 3.9 only security fixes stdlib Python modules in the Lib dir labels Sep 17, 2019
    @vstinner
    Copy link
    Member Author

    See also bpo-37424 was has been fixed: "subprocess.run timeout does not function if shell=True and capture_output=True".

    @vstinner
    Copy link
    Member Author

    Hum, I see a similar behavior on Linux. Try attached communicate_close.py (I added newlines for readability):
    ---
    vstinner@apu$ python3 communicate_close.py
    process 1: pid 13089
    process 1: process 2 spawned (pid 13090)
    process 1: stdout pipe os.stat_result(st_mode=4480, st_ino=3107861, st_dev=12, st_nlink=1, st_uid=1000, st_gid=1000, st_size=0, st_atime=1568816000, st_mtime=1568816000, st_ctime=1568816000)
    process 1: communicate with process 2 (pid 13090) ...

    process 2: pid 13090
    process 2: stdout os.stat_result(st_mode=4480, st_ino=3107861, st_dev=12, st_nlink=1, st_uid=1000, st_gid=1000, st_size=0, st_atime=1568816000, st_mtime=1568816000, st_ctime=1568816000)

    process 3: pid 13092
    process 3: stdout os.stat_result(st_mode=4480, st_ino=3107861, st_dev=12, st_nlink=1, st_uid=1000, st_gid=1000, st_size=0, st_atime=1568816000, st_mtime=1568816000, st_ctime=1568816000)

    process 1 (thread): kill process 2 (pid 13090)
    process 1 (thread): close process 2 stdout pipe (fd 3)

    process 3: exit
    process 1: communicate with process 2 (pid 13090) ... done in 5.1 sec
    ---

    In process 1, communicate(<process 2>) does not complete immediately when the process 1 thread kills process 2 and closes process 2 stdout pipe.

    communicate() only completes once process 3 completes.

    The stdout file of process 2 and process 3 are the same file.

    @vstinner
    Copy link
    Member Author

    vstinner commented Oct 8, 2019

    New changeset 0ec618a by Victor Stinner in branch 'master':
    bpo-37531: regrtest ignores output on timeout (GH-16659)
    0ec618a

    @miss-islington
    Copy link
    Contributor

    New changeset 598bfa4 by Miss Islington (bot) in branch '3.7':
    bpo-37531: regrtest ignores output on timeout (GH-16659)
    598bfa4

    @miss-islington
    Copy link
    Contributor

    New changeset 359a197 by Miss Islington (bot) in branch '3.8':
    bpo-37531: regrtest ignores output on timeout (GH-16659)
    359a197

    @vstinner
    Copy link
    Member Author

    vstinner commented Oct 9, 2019

    regrtest now workarounds this issue using timeouts on subprocess.Popen.wait() and threading.Thread.join() operations: see bpo-37531.

    @vstinner vstinner changed the title subprocess: On Windows, Popen.kill() + Popen.communicate() is blocking until all processes using the pipe close the pipe subprocess: Popen.kill() + Popen.communicate() is blocking until all processes using the pipe close the pipe Oct 16, 2019
    @vstinner
    Copy link
    Member Author

    See also bpo-31447: "proc communicate not exiting on python subprocess timeout using PIPES".

    @vstinner
    Copy link
    Member Author

    On Windows, the threads reading pipes continue to run even after the direct child process exited.

    Problem: at Python exit (main process), Python hangs on calling threading._shutdown() which waits until all Python threads complete.

    One enhancement would be to spawn subprocess.Popen.communicate() internal threads as daemon threads. So threading._shutdown() would not wait for them at Python exit.

    @vstinner
    Copy link
    Member Author

    vstinner commented Feb 7, 2020

    My use case was specific to regrtest. I solved the issue differently in regrtest. I close the issue.

    @vstinner vstinner closed this as completed Feb 7, 2020
    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    3.9 only security fixes stdlib Python modules in the Lib dir
    Projects
    None yet
    Development

    No branches or pull requests

    2 participants