Python subprocess logging to logger from stdout/stderr

logging_subprocess.py

#!/usr/local/bin/python3

import logging, select, subprocess

LOG_FILE = "test.log"
logger = logging.getLogger(__name__)
logging.basicConfig(level=logging.INFO,filename=LOG_FILE,format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

def logging_call(popenargs, **kwargs):
    process = subprocess.Popen(popenargs, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)

    def check_io():
           while True:
                output = process.stdout.readline().decode()
                if output:
                    logger.log(logging.INFO, output)
                else:
                    break

    # keep checking stdout/stderr until the child exits
    while process.poll() is None:
        check_io()

def main():
    logging_call(["ls", "-l"])

if __name__ == "__main__":
    try:
        main()
    except KeyboardInterrupt:
        logging.warning("Stopping...")

From the log output, it's logging like this

2017-07-21 10:55:58,336 - __main__ - INFO - -rw-r--r--  1 admin  staff   226 Jul 21 08:57 main1.py

2017-07-21 10:55:58,336 - __main__ - INFO - -rw-r--r--  1 admin  staff   767 Jul 21 10:15 main2.py

A simple test ( modify your code)

    def check_io():
           while True:
                output = process.stdout.readline().decode()
                if output:
                    logger.log(logging.INFO, output)
                    print(output)
                    time.sleep(1)

We can see logger is logging output from check_io line by line. That's not correct ( or best practices).

Expecting the whole output in one line.

@pilgrim2go, why do you have a time.sleep(1) in your code sample? Are you essentially buffering, and then printing it out to the log file.. to have more lines?

Whats the best practice here? Particularly for long running processes?

Thank you for the code snippet. Works beautifully for most part except when the process terminates immediately. In this case, only the first line is printed. A small tweak in your code helps:

     def logs(read_till_end=False):
            ready_to_read = select.select([self.child.stdout, self.child.stderr], [], [], 1000)[0]
            for io in ready_to_read:
                line = 'gibberish'
                while line:
                    line = io.readline()
                    if line:
                        self.logger.log(log_level[io], line[:-1])
                        if not read_till_end:
                            break
    
        # keep checking stdout/stderr until the child exits
        while self.child.poll() is None:
            logs()
    
        logs(read_till_end=True)  # check again to catch anything after the process exits
        self.child.wait() # wait for the child process to terminate

Using a read_till_end parameter, I can instruct the function to read till the end of the stream.

Hi 👋

I've done a rewrite from scratch:

• Using py 3.7+ text kwarg so it works on Windows special chars as well
• Using two threads in order to handle stdout and stderr separately i.e. logging.INFO and logging.ERROR

https://gist.github.com/ddelange/6517e3267fb74eeee804e3b1490b1c1d