stdout printed in stderr file while using logger

Question

Im using logger to print out stdout and stderr to log files. I've done this:

def log(process):

    logger = logging.getLogger('logging_errors')
    if not len(logger.handlers):
        logger.setLevel(logging.DEBUG)
        formatter = logging.Formatter('%(levelname)s %(asctime)s %(module)s %(message)s')

        handler_stderr = logging.FileHandler('stderr.log')
        handler_stderr.setLevel(logging.WARNING)
        handler_stderr.setFormatter(formatter)
        logger.addHandler(handler_stderr)

        handler_stdout = logging.FileHandler('stdout.log')
        handler_stdout.setLevel(logging.DEBUG)
        handler_stdout.setFormatter(formatter)
        logger.addHandler(handler_stdout)
    return logger.error(process.stderr.read())
    return logger.info(process.stdout.read())

A process is passed onto this function which can be something like this:

proc = subprocess.Popen(['FastTree -nt test.fasta'], stdin = None, stdout = subprocess.PIPE, stderr = subprocess.PIPE, shell=True) 
proc.wait()
log(proc)

The problem I have is that the stdout is not getting printed to the stdout.log file, I get the stderr in stdout.log file. stderr.log file is correct. Any pointers on this?

score 2 · Answer 1 · answered Jun 20 '13 at 09:00

2

You have

return logger.error(process.stderr.read())
return logger.info(process.stdout.read())

The second return statement doesn't get executed, so the process' stdout is never logged. Just remove return from those statements, and you should find that output appears in stdout.log.

You're getting stderr output in stdout.log because the all logged events are passed to both handlers.

answered Jun 20 '13 at 09:00

Vinay Sajip

95,872
14
179
191

I did that and I did get the correct stdout but it only runs for one process. I added an additional process but it ignored it. – bioinf80 Jun 20 '13 at 09:10

score 0 · Answer 2 · edited May 23 '17 at 10:25

You could setup two loggers, one for stdout and one for stderr, but then you would have to write

info_logger.info(out)
error_logger.error(err)

And that is repetitious since you would have to choose both the appropriate logger and the appropriate level when they both contain essentially the same information.

So, we could get a little fancier and use robert's LevelFilter to create one logger with two filtered handlers. The handlers each have a filter to accept only those LogRecords whose level is less than or equal to end_level:

handler.addFilter(LevelFilter(end_level))

Meanwhile, the statement

handler.setLevel(begin_level)

causes handler to accept only those LogRecords whose level is greater than begin_level. Combined, we have a handler that accepts only those LogRecords whose level is between begin_level and end_level. Thus, you could have one handler handle DEBUG and INFO LogRecords, and a second handler for WARNING, ERROR and CRITICAL LogRecords.

Putting it all together, you could use something like this:

import logging
import subprocess

class LevelFilter(logging.Filter):
    """
    https://stackoverflow.com/a/7447596/190597 (robert)
    """
    def __init__(self, level):
        self.level = level

    def filter(self, record):
        return record.levelno <= self.level

def splitlevel_logger(name, outpath='stderr.log', errpath='stdout.log',
                      fmt='%(levelname)s %(asctime)s %(module)s %(message)s'):
    formatter = logging.Formatter(fmt)
    logger = logging.getLogger()
    logger.setLevel(logging.DEBUG)
    for filename, begin_level, end_level in (
            (outpath, logging.WARNING, logging.CRITICAL),
            (errpath, logging.DEBUG, logging.INFO)):
        handler = logging.FileHandler(filename, 'w')
        handler.setLevel(begin_level)
        handler.addFilter(LevelFilter(end_level))
        handler.setFormatter(formatter)
        logger.addHandler(handler)
    return logger

def log(out='', err=''):
    if out:
        logger.info(out)
    if err:
        logger.error(err)

logger = splitlevel_logger(__name__)
cmd = 'FastTree -nt test.fasta'
proc = subprocess.Popen(cmd,
                        stdout = subprocess.PIPE,
                        stderr = subprocess.PIPE, shell=True) 
log(*proc.communicate())

By the way, note the warning concerning subprocess.Popen.wait:

Warning

[Popen.wait] will deadlock when using stdout=PIPE and/or stderr=PIPE and the child process generates enough output to a pipe such that it blocks waiting for the OS pipe buffer to accept more data. Use communicate() to avoid that.

So it is potentially buggy to use Popen.wait in the situation you have above. Use Popen.communicate to avoid this problem. Or, if you want to read and log output as it comes out of the subprocess (instead of recieving it only after the subprocess completes) use threading or select.select.

stdout printed in stderr file while using logger

2 Answers2