python subprocess poll() is not returning None even if Popen is still running

Question

I have a python script that executes linux commands with timeout using a while loop and sleep like below

fout = tempfile.TemporaryFile()
try:
    p = subprocess.Popen(["/bin/bash","-c", options.command], bufsize=-1, shell=False, preexec_fn=os.setsid, stdin=subprocess.PIPE, stdout=fout, stderr=subprocess.PIPE)
except:
    sys.exit(UNEXPECTED_ERROR)
if options.timeout:
    print "options.timeout = %s" % options.timeout
    elapsed = 0
    time.sleep(0.1) # This sleep is for the delay between Popen and poll() functions
    while p.poll() is None:
        time.sleep(1)
        elapsed = elapsed + 1
        print "elapsed = %s" % elapsed
        if elapsed >= options.timeout:
            # TIMEDOUT
            # kill all processes that are in the same child process group
            # which kills the process tree
            pgid = os.getpgid(p.pid)    
            os.killpg(pgid, signal.SIGKILL)
            p.wait()
            fout.close()
            sys.exit(TIMEOUT_ERROR)
            break
else:
    p.wait()

fout.seek(0) #rewind to the beginning of the file
print fout.read(),
fout.close()
sys.exit(p.returncode)

$ time myScript -c "cat file2" 2>&1 -t 5
options.timeout = 5
elapsed = 1

real    0m11.811s
user    0m0.046s
sys     0m1.153s

My question is in that above case even if the timeout is 5 seconds cat continues till it finishes. Am I missing something here? Please help.

I think it might be possible that `cat` put all the data in the output stream, but your terminal is too slow to read it all. What happens if you try a command like: `while : ; do echo "hi"; sleep 1; done` ? — mgilson, Oct 19 '12 at 19:23
Can you elaborate a bit on what you're seeing? The output you pasted looks like the while loop exited after the first run through the loop. It doesn't appear that it should have gone into the timeout code. — Kurt Stutsman, Oct 19 '12 at 19:30
`$ time my_script -c "while : ; do echo "hi"; sleep 1; done" 2>&1 -t 5 options.timeout = 5 elapsed = 1 elapsed = 2 elapsed = 3 elapsed = 4 elapsed = 5 real 0m5.155s user 0m0.039s sys 0m0.012s` It seems that while "hi" is working fine with the timeout. Can you elaborate on what's happening in my case where I did a cat of a 100MB file filled with /dev/zero — yalkris, Oct 19 '12 at 19:31
@KurtStutsman I am trying to cat a file of 100MB filled with /dev/zero. ]`$ time cat file2 real 0m10.481s user 0m0.004s sys 0m0.734s ` — yalkris, Oct 19 '12 at 19:41

jfs · Accepted Answer · 2012-10-22T11:08:18.773

It works as expected on Ubuntu:

$ /usr/bin/ssh root@localhost -t 'sync && echo 3 > /proc/sys/vm/drop_caches'
$ /usr/bin/time python2.4 myscript.py 'cat big_file'
timeout
done
0.01user 0.63system 0:05.16elapsed 12%CPU 

$ /usr/bin/ssh root@localhost -t 'sync && echo 3 > /proc/sys/vm/drop_caches'
$ /usr/bin/time cat big_file >/dev/null
0.02user 0.82system 0:09.93elapsed 8%CPU

It also work with a shell command:

$ /usr/bin/time python2.4 myscript.py 'while : ; do sleep 1; done'
timeout
done
0.02user 0.00system 0:05.03elapsed 0%CPU

Assumptions:

you can't use time.time() due to possibility of a system clock change
time.clock() doesn't measure children times on Linux
we can't emulate time.monotonic() from Python 3.3 in pure Python due to ctypes is not available on Python 2.4
it is acceptable to survive hibernation e.g., 2 seconds before hibernation + 3 seconds after computer wakes up whenever it happens if timeout is 5 seconds.

#!/usr/bin/env python2.4
import os
import signal
import sys
import tempfile
import time
from subprocess import Popen

class TimeoutExpired(Exception):
    pass

def wait(process, timeout, _sleep_time=.1):
    for _ in xrange(int(timeout * 1. / _sleep_time + .5)):
        time.sleep(_sleep_time)  # NOTE: assume it doesn't wake up earlier
        if process.poll() is not None:
            return process.wait()
    raise TimeoutExpired  # NOTE: timeout precision is not very good

f = tempfile.TemporaryFile() 
p = Popen(["/bin/bash", "-c", sys.argv[1]], stdout=f, preexec_fn=os.setsid,
          close_fds=True)
try:
    wait(p, timeout=5)
except TimeoutExpired:
    print >>sys.stderr, "timeout"
    os.killpg(os.getpgid(p.pid), signal.SIGKILL)
    p.wait()
else:
    f.seek(0)
    for line in f:
        print line,
f.close()  # delete it
print >>sys.stderr, "done"

I tried your script like this `$ ls -alrt file2` -rw-r--r-- 1 root root 104857600 Oct 19 14:56 file2 `$ time cat file2` real 0m10.468s user 0m0.011s sys 0m0.710s `$ time your_script "cat file2"` done real 0m11.360s user 0m0.152s sys 0m1.278s — yalkris, Oct 22 '12 at 16:16
my file 2 is created by this dd command `dd if=/dev/zero of=./file2 bs=100M count=1` — yalkris, Oct 22 '12 at 16:22
Thanks for your replies. Your script didn't timeout in 5 seconds. Let me know if cat of a file filled with /dev/zero behaves differently than other files or if I am missing something — yalkris, Oct 22 '12 at 16:25
@yalkris: there is no timeout because `cat` finishes *before* 5 seconds. The rest of time is spend printing zero bytes in the `for line in f` loop (a single iteration because there is no newline in the file) that on my terminal has no visible output (try `cat -v file2` to see zero bytes). If you redirect `your_script` stdout to devnull it should end in under a second: `time with_timeout "cat file2" >/dev/null`. You could limit the execution time of the whole script if you'd like (e.g., just call itself [similar to this](http://stackoverflow.com/a/12965611/4279)) — jfs, Oct 22 '12 at 20:48

glglgl · Answer 2 · 2012-10-19T20:34:09.920

Beside of the problems I see in your code

you call Popen() with stdin=subprocess.PIPE and stderr=subprocess.PIPE. But you never handle these pipes. With a command like cat file2, this should be fine, but it can lead to problems.

I can spot a potential misbehaviour: you might have mixed up indentation (as in the 1st version of your question). Assume you have the following:

while p.poll() is None:
    time.sleep(1)
    elapsed = elapsed + 1
    print "elapsed = %s" % elapsed
    if elapsed >= options.timeout:
        # TIMEDOUT
        # kill all processes that are in the same child process group
        # which kills the process tree
        pgid = os.getpgid(p.pid)    
        os.killpg(pgid, signal.SIGKILL)
    p.wait()
    fout.close()
    sys.exit(TIMEOUT_ERROR)
    break

You don't reach the timeout threshold, and nevertheless p.wait() is called due to a bad indentation. Don't mix up tabs and spaces; PEP 8 suggests to use spaces only and a indentation depth of 4 columns.

My apologies. `poll()` is not returning None even if process is still running. May be a newbie question but how to handle stdin and stderr pipes differently?It will help if you can please point me to related links on how to handle pipes. I was using pexpect with timeout before but faced problems because pexpect timeout is sensitive to system time changes. So I resorted to using this above python code. My question above was if subprocess "cat" takes 11 seconds to process why does my poll() function run only once? — yalkris, Oct 19 '12 at 20:37
I checked indentation in my script. It's not the problem. I still see my subprocess running 11 seconds with that above while loop. — yalkris, Oct 19 '12 at 20:48

python subprocess poll() is not returning None even if Popen is still running

2 Answers2