Redirecting subprocess stdout and stderr to standard loggers with gevent

Question

I've set out to write a subprocess manager in Python 2.7.10 with gevent 1.0.1. It seems relevant, so I'll also note that I'm working on a desktop x64 Windows 10.

One of the core features of a subprocess manager would be redirecting the output of subprocesses to rotating files. I assumed using the standard RotatingFileLogger would make this easy to accomplish. Achieving non-blocking I/O should be possible through gevent.

My first step is to write a Proof of Concept demonstrating the approach, but I'm struggling with what I perceive to be basic gevent concepts.

The log files appear just fine when I run my PoC, and they get filled as the process is running, but when the process ends, everything just halts. I guess something is deadlocking.

I have written the following gevent.Greenlet subclass LogPipe which will pulls from stdout and stderr and feeds it to a standard logger:

class LogPipe(gevent.Greenlet):
    """
    inspiration: http://codereview.stackexchange.com/questions/6567/redirecting-subprocesses-output-stdout-and-stderr-to-the-logging-module/17959#17959
    """
    def __init__(self, logger, level):
        gevent.Greenlet.__init__(self)

        self._logger = logger
        self._level = level

        self._fd_read, self._fd_write = os.pipe()
        self._pipe_reader = os.fdopen(self._fd_read)

    def fileno(self):
        return self._fd_write

    def _run(self):
        for line in iter(self._pipe_reader.readline, b''):
            self._logger.log(self._level, line.strip())
        self._pipe_reader.close()

    def close(self):
        os.close(self._fd_write)

    def __str__(self):
        return "LogPipe for logger {} ({})".format(self._logger.name, gevent.Greenlet.__str__(self))

Here's the SubprocessManager, also a subclass of gevent.Greenlet, and the test case at the bottom:

from __future__ import (absolute_import, division,
                        print_function, unicode_literals)
from builtins import *

import os
import logging
import logging.handlers
import gevent
from gevent.subprocess import Popen

class SubprocessManager(gevent.Greenlet):
    def __init__(self, name, command, log_dir=""):
        gevent.Greenlet.__init__(self)

        self._name = name
        self._args = command

        log_dir = log_dir if os.path.exists(log_dir) else os.getcwd()

        formatter = logging.Formatter('%(message)s')

        self._stdout_logger = logging.getLogger("{}.stdout".format(self._name))
        self._stdout_logger.setLevel(logging.INFO)
        stdout_log_file = os.path.join(log_dir, self._stdout_logger.name)
        stdout_handler = logging.handlers.RotatingFileHandler(stdout_log_file, maxBytes=4096, backupCount=5)
        stdout_handler.setFormatter(formatter)
        self._stdout_logger.addHandler(stdout_handler)

        self._stderr_logger = logging.getLogger("{}.stderr".format(self._name))
        self._stderr_logger.setLevel(logging.INFO)
        stderr_log_file = os.path.join(log_dir, self._stderr_logger.name)
        stderr_handler = logging.handlers.RotatingFileHandler(stderr_log_file, maxBytes=4096, backupCount=5)
        stderr_handler.setFormatter(formatter)
        self._stderr_logger.addHandler(stderr_handler)

    def _run(self):
        stdout_pipe = logutil.LogPipe(self._stdout_logger, logging.INFO)
        stdout_pipe.start()
        stderr_pipe = logutil.LogPipe(self._stderr_logger, logging.INFO)
        stderr_pipe.start()
        try:
            sp = Popen(self._args, stdout=stdout_pipe, stderr=stderr_pipe, bufsize=1)
            return_code = sp.wait()
        finally:
            stdout_pipe.close()
            stderr_pipe.close()
        return return_code


if __name__ == "__main__":
    m = SubprocessManager("test", "test.bat")
    m.start()
    gevent.wait()

test.bat:

echo "starting"
ping 127.0.0.1 -n 5 -w 1000 > NUL
echo "bla blasdfasdf"
ping 127.0.0.1 -n 5 -w 1000 > NUL
echo "bla blasdfas   df"
ping 127.0.0.1 -n 5 -w 1000 > NUL
echo "done!"

requirements.txt:

future
gevent==1.0.1

So my question is, why is this code deadlocking? When I use a debugger, it seems like the final call to readline in LogPipe is never returning.

to help answer the question, you could [remove unnecessary parts and create a standalone code example](http://stackoverflow.com/help/mcve). Here's [how to log (display) both stdout/stderr while capturing the output for later using `asyncio`](http://stackoverflow.com/a/25960956/4279) (you could pass `logger.info` as `display` parameter). — jfs, Oct 21 '15 at 13:51
Thanks for the link. Aside of that, what parts of this post would you consider 'unnecessary'? I crafted this code specifically to be a 'standalone' example. — Korijn, Oct 21 '15 at 14:25
it is simple: if you have removed the part and the code still deadlocks then the part is unnecessary (e.g., logging handlers, formatters are probably unrelated to the issue as long as you have a valid `fileno()`). — jfs, Oct 21 '15 at 14:33
Right. Well, in this case the deadlocking is related to the fact that I'm using 2 greenlets that are reading from 2 pipes from 1 other greenlet, so I considered all of that relevant (because it didn't deadlock before I switched to this setup). — Korijn, Oct 21 '15 at 14:55
http://stackoverflow.com/questions/19497587/get-live-stdout-from-gevent-subprocess — engineerC, Oct 24 '15 at 22:04

Redirecting subprocess stdout and stderr to standard loggers with gevent

0 Answers0