subprocess.check_output с завершением процесса завершения ожидания отложено

Question

У меня есть следующий код, который должен начинать работу и убивать процесс, если требуется слишком много времени для завершения.

import random 
from datetime import datetime 
from subprocess import check_output, STDOUT, TimeoutExpired 

MAX_WAIT = 5 

def custom_task(job=None): 
    sec = job or random.randint(4,10) 
    print('\nThis task will sleep {s} sec.'.format(s=sec)) 
    print('-/- {time} - - Commence new job <{job}>'.format(
      job=sec, time=datetime.now())) 
    try: 
     cmd = 'sleep {s}; echo "Woke up after {s} sec." | tee -a task.log'.format(s=sec) 
     stdout = check_output(cmd, shell=True, stderr=STDOUT, timeout=MAX_WAIT).decode() 
    except TimeoutExpired: 
     print('~/~ {time} - - Job <{job}> has been cancelled'.format(
       job=sec, time=datetime.now())) 
    except Exception as err: 
     print('!/! {time} - - Job <{job}> could not finish because of the error'.format(
       job=sec, time=datetime.now())) 
     print('{err}'.format(err=err)) 
    else: 
     print('=/= {time} - - Job <{job}> has been done'.format(
       job=sec, time=datetime.now())) 
     print(stdout) 

custom_task(4) 
custom_task(8) 

Консоль дает мне следующий вывод:

This task will sleep 4 sec. 
-/- 2016-11-03 01:07:56.037104 - - Commence new job <4> 
=/= 2016-11-03 01:08:00.051072 - - Job <4> has been done 
Woke up after 4 sec. 


This task will sleep 8 sec. 
-/- 2016-11-03 01:08:00.051233 - - Commence new job <8> 
~/~ 2016-11-03 01:08:08.062563 - - Job <8> has been cancelled 

Заметьте, что задача, которая должна была спать 8 сек выпустила блок через 8 секунд, а не после того, как ожидается, MAX_WAIT = 5

Но если я проверка tasks.log Я вижу:

Woke up after 4 sec. 

Это означает, что t только 4 секунды задача успешно завершена, что желательно и ожидается. Следовательно, мой сценарий работает, но довольно неожиданным и нежелательным образом.

Есть ли способ освободить блок (убить процесс) вовремя, таким образом, как только MAX_WAIT превышен тайм-аут?

И что здесь происходит, почему python ждет, пока sleep не закончит спать?

РЕДАКТИРОВАТЬ - рабочий пример

from random import randint 
from os import killpg 
from signal import SIGKILL 
from datetime import datetime 
from subprocess import Popen, STDOUT, TimeoutExpired, PIPE 

MAX_WAIT = 5 

def custom_task(job=None): 
    sec = job or randint(4,10) 
    print('\n# This task will sleep {s} sec.'.format(s=sec)) 
    print('-/- {time} - - Commence new job <{job}>'.format(
      job=sec, time=datetime.now())) 
    cmd = 'sleep {s}; echo "Woke up after {s} sec." | tee -a tasks.log'.format(s=sec) 
    with Popen(cmd, shell=True, 
       stdout=PIPE, stderr=STDOUT, 
       close_fds=True, 
       universal_newlines=True, 
       start_new_session=True) as proc: 
     try: 
      stdout = proc.communicate(timeout=MAX_WAIT)[0] 
     except TimeoutExpired: 
      print('~/~ {time} - - Job <{job}> has been cancelled'.format(
        job=sec, time=datetime.now())) 
      killpg(proc.pid, SIGKILL) 
      stdout = proc.communicate(timeout=1)[0] 
     except Exception as err: 
      print('!/! {time} - - Job <{job}> could not finish because of the error'.format(
        job=sec, time=datetime.now())) 
      print('{err}'.format(err=err)) 
      killpg(proc.pid, SIGKILL) 
     else: 
      print('=/= {time} - - Job <{job}> has been done'.format(
        job=sec, time=datetime.now())) 
     print('# Return code: {}'.format(proc.returncode)) 
     print(stdout) 

custom_task(4) 
custom_task(30) 

ВЫХОД

$ time python3 popen.py 

# This task will sleep 4 sec. 
-/- 2016-11-05 15:38:13.833871 - - Commence new job <4> 
=/= 2016-11-05 15:38:17.842769 - - Job <4> has been done 
# Return code: 0 
Woke up after 4 sec. 


# This task will sleep 30 sec. 
-/- 2016-11-05 15:38:17.842942 - - Commence new job <30> 
~/~ 2016-11-05 15:38:22.849511 - - Job <30> has been cancelled 
# Return code: -9 


real 0m9.095s 
user 0m0.087s 
sys 0m0.000s 

Answer 1

Есть фактически несколько процессов называемые в check_output вызова. Поэтому, когда subprocess отправляет сигнал kill, он не будет отправлен всем процессам потомок. check_output может дождаться завершения других процессов. Для решения посмотрите на это post на StackOverflow.