classification
Title: subprocess.check_output() with timeout does not exit if child process does not generate output after timeout
Type: behavior Stage: patch review
Components: Library (Lib) Versions: Python 3.5, Python 2.7
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: Mike Lewis, eryksun, fangyizhou
Priority: normal Keywords: patch

Created on 2018-02-08 09:11 by Mike Lewis, last changed 2018-02-14 14:17 by eryksun.

Files
File name Uploaded Description Edit
timeout_examples.tgz Mike Lewis, 2018-02-08 09:11 Python 2.7 and Python 3 examples recreating the issue
Pull Requests
URL Status Linked Edit
PR 5684 closed fangyizhou, 2018-02-14 12:14
Messages (6)
msg311820 - (view) Author: Mike Lewis (Mike Lewis) Date: 2018-02-08 09:11
When using a timeout with check_output(), the call does not terminate unless the child process generates output after the timeout. Looking at the code, it appears there is a second call to communicate() after the timeout has happened, presumably to retrieve any remaining output. This call appears to hang until the child process generates output.

I have two test cases (for Python 2.7 / subprocess32 and Python 3 / subprocess respectively). They show the same behaviour, the Python 2.7 version has been reproduced on Ubuntu 16.04.3 and Centos 7 and the Python 3 version on Ubuntu 16.043.

Each test case has a first example where bash executes a long sleep before generating output and where the timeout is not respected, and a second example that generates output at intervals and the timeout is respected.

Relevant code also attached below for reference:

then = time.time()
print("Subprocess with idle stdout at timeout: start at {}".format(then))
try:
    output = subprocess.check_output(["bash", "-c",
                                        "echo Subcall; sleep 5; echo Done;"],
                                       stderr=subprocess.STDOUT, timeout=1)
    now = time.time()
    print("Finish at: {}, {:.0f} seconds".format(now, now-then))
    print(output)
except subprocess.TimeoutExpired as te:
    now = time.time()
    print("Timed out at: {}, {:.0f} seconds".format(now, now-then))

then = time.time()
print("Generating stdout from subprocess: start at ", then)
try:
    output = subprocess.check_output(["bash", "-c",
                                        "echo Subcall; for i in 1 2 3 4 5; do sleep 1; echo $i; done; echo Done;"],
                                       stderr=subprocess.STDOUT, timeout=1)
    now = time.time()
    print("Finish at: {}, {:.0f} seconds".format(now, now-then))
    print(output)
except subprocess.TimeoutExpired as te:
    now = time.time()
    print("Timed out at: {}, {:.0f} seconds".format(now, now-then))
msg311821 - (view) Author: Mike Lewis (Mike Lewis) Date: 2018-02-08 09:12
Example of the output:

$ ./timeout.py
Subprocess with idle stdout at timeout: start at  1518081130.44
Timed out at: 1518081135.45, 5 seconds
Generating stdout from subprocess: start at  1518081135.45
Timed out at: 1518081136.47, 1 seconds

As you see, the 1 second timeout is respected in the second case where the child process is generating output.
msg312117 - (view) Author: Fangyi Zhou (fangyizhou) * Date: 2018-02-13 12:45
I think the issue is that the process is not terminated.

If you increase the sleep duration, you would see that the sleep process is not killed by SIGKILL.
msg312135 - (view) Author: Fangyi Zhou (fangyizhou) * Date: 2018-02-13 18:35
As far as I have discovered, the bash process is killed by after the timeout. Presumably the pipe is still open due to the sleep process, so in order to retrieve any output from stdout/stderr, the read waits on the pipe, hence leading to timeout not respected.

We can fix this issue in 2 ways 
(1) kill process tree when timeout happens
(2) force closing the pipes after timeout, but this will leave the sub-processes detached and it will be kept running

I don't know which way is better, hopefully someone with more knowledge can engage in the discussion.
msg312172 - (view) Author: Fangyi Zhou (fangyizhou) * Date: 2018-02-14 12:15
I choose to implement the first way. I believe this is in favour in prevention of resource leaks and zombie processes.

https://github.com/python/cpython/pull/5684
msg312175 - (view) Author: Eryk Sun (eryksun) * (Python triager) Date: 2018-02-14 14:17
Work on related issues extends back 9 years to issue 5115. Also see issue 26534.
History
Date User Action Args
2018-02-14 14:17:03eryksunsetnosy: + eryksun
messages: + msg312175
2018-02-14 12:15:09fangyizhousetmessages: + msg312172
2018-02-14 12:14:12fangyizhousetkeywords: + patch
stage: patch review
pull_requests: + pull_request5480
2018-02-13 18:35:12fangyizhousetmessages: + msg312135
2018-02-13 12:45:17fangyizhousetnosy: + fangyizhou
messages: + msg312117
2018-02-08 09:12:59Mike Lewissetmessages: + msg311821
2018-02-08 09:11:07Mike Lewiscreate