CODEWITHSUNDEEP
pythonloggingstdoutstderr
bioinf80
bioinf80

Reputation: 573

stdout printed in stderr file while using logger

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?

Upvotes: 0

Views: 649

Answers (2)

unutbu
unutbu

Reputation: 879481

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.

Upvotes: 0

Vinay Sajip
Vinay Sajip

Reputation: 99355

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.

Upvotes: 2

Related Questions