How can I asynchronously capture output from a long-running Python subprocess

Question

For a test I want to start a long-running Python 3 script on Linux, capture some of its output, check that it's as expected and kill it again.

I'm just trying to get the general framework working for now.

When I run the following code, I would expect the output to include line = "0" -- the python script just prints out an increasing sequence of integers, one per second. Instead, that for loop is skipped completely.

import subprocess
from tempfile import NamedTemporaryFile
import time
import unittest

import asynchronousfilereader

class TestProcessSpawning(unittest.TestCase):
    def test_spawning_counter(self):
        counter_code = \
"""
import time
i = 0
while True:
    print(i)
    i = i + 1
    time.sleep(1)
"""

        with NamedTemporaryFile(mode="w", suffix='.py', delete=False)\
                as temp_file:
            temp_file.write(counter_code)
            file_name = temp_file.name

            # proc = subprocess.Popen(['ping', 'localhost'],
            #                         stdout=subprocess.PIPE, close_fds=True)
            proc = subprocess.Popen(['python3', file_name],
                                    stdout=subprocess.PIPE, close_fds=True)

            time.sleep(3)

            assert proc.returncode is None  # None => still running

            reader = asynchronousfilereader.AsynchronousFileReader(proc.stdout)

            time.sleep(3)  # give it a chance?

            for line in reader.readlines():
                print('line = "{}"'.format(line))
                break  # just grab first one

            proc.kill()

However, if I change ['python3', file_name] to ['ping', 'localhost'] I do get a line of output from ping (I'm running on Linux so ping keeps producing output until you stop it).

Any idea why this seems to work ok for other types of subprocess but not for python?

Notes:

this code uses the asynchronousfilereader available from pip
if I just run python3 <temp_file_name> in a shell, the script runs as expected, printing 0, 1, 2, ...
the process return code of None after a few seconds suggests the process gets run (i.e. doesn't just crash)
I have tried running it through unbuffer as suggested here: the output did not appear
I tried passing bufsize=1 to Popen: the output did not appear
if I include the -v flag I get lots of output, including this, which suggests python is trying to run interactively even though I've provided a file name:

Python 3.5.2 (default, Nov 23 2017, 16:37:01)

[GCC 5.4.0 20160609] on linux

Type "help", "copyright", "credits" or "license" for more information.

I updated the duplicate target. Your issue is that you don't flush the output buffer in the subprocess. Either run with the `-u` switch, or add `flush=True` to your `print()` calls. — Martijn Pieters, Dec 06 '17 at 10:16
Note that you have some imports missing (`NamedTemporaryFile`, `time`) and that the `with ... as` statement must be on a single line. — Martijn Pieters, Dec 06 '17 at 10:20
@MartijnPieters I had already tried `-u` and have just tried `flush=True`. I still don't get the output. Thanks for telling me about the import problems -- I'll fix it up. — Matthew Strawbridge, Dec 06 '17 at 10:22
I notice that the reader thread is no longer alive; so the `line = self._fd.readline()` read call in the thread returned an empty response the first time round or quite quickly. — Martijn Pieters, Dec 06 '17 at 10:27
`-v` shows what Python imports, and always includes the copyright notice. It is not running anything interactively. — Martijn Pieters, Dec 06 '17 at 10:41

Martijn Pieters · Accepted Answer · 2017-12-06T11:08:38.573

1

You need to flush the file you write:

with NamedTemporaryFile(mode="w", suffix='.py', delete=False) as temp_file:
    temp_file.write(counter_code)
    temp_file.flush()

Your program is too short to ever make it out of the buffer otherwise, and you are running an empty file.

I'd also make sure the program then flushes on every write; either run python3 -u for unbuffered stdout or use flush=True on every print. That way you don't have to add so many sleeps in your parent program.

With these changes, the unittest prints

line = "b'0\n'"

and several warnings about the subprocess still running and the stdout buffer still being open before completing.

edited Dec 06 '17 at 11:08

answered Dec 06 '17 at 10:45

Martijn Pieters

1,048,767
296
4,058
3,343

Aha, many thanks! It was indeed fixed by flushing `temp_file`. Because I had looked at some of the generated files, and indeed run them, I had incorrectly assumed that they would be fully populated at the point of creating the subprocess. – Matthew Strawbridge Dec 06 '17 at 12:20

How can I asynchronously capture output from a long-running Python subprocess

1 Answers1