Python logger - Redirecting STDOUT to logfile as well as any debug messages

Question

I'm trying to use the logging module in Python so that, when I run my program, I end up with a log file, debug.log, containing:

1. Every log message (logging.DEBUG, logging.WARNING etc.)
2. Every time my code prints something to STDOUT

When I run the program, I only want the debug messages to appear in the log file, not to be printed on the terminal.

Based on this answer, here's my example code, test.py:

import logging
import sys

root = logging.getLogger()
root.setLevel(logging.DEBUG)

fh = logging.FileHandler('debug.log')
fh.setLevel(logging.DEBUG)

sh = logging.StreamHandler(sys.stdout)
sh.setLevel(logging.DEBUG)

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
sh.setFormatter(formatter)
fh.setFormatter(formatter)

root.addHandler(sh)
root.addHandler(fh)

x = 4
y = 5
logging.debug("X: %s", x)
logging.debug("Y: %s", y)
print("x is", x)
print("y is", y)
print("x * y =", x*y)
print("x^y =", x**y)

And here's what I would want to be the contents of debug.log:

2021-02-01 12:10:48,263 - root - DEBUG - X: 4                            
2021-02-01 12:10:48,264 - root - DEBUG - Y: 5
x is 4
y is 5
x * y = 20
x^y = 1024

Instead, the contents of debug.log is just the first two lines:

2021-02-01 12:10:48,263 - root - DEBUG - X: 4                            
2021-02-01 12:10:48,264 - root - DEBUG - Y: 5

When I run test.py, I get this output:

2021-02-01 12:17:04,201 - root - DEBUG - X: 4
2021-02-01 12:17:04,201 - root - DEBUG - Y: 5
x is 4
y is 5
x * y = 20
x^y = 1024

So I've actually got the opposite results to what I want: the log file excludes STDOUT prints where I want them included, and the program output includes the debug messages where I want them excluded.

How can I fix this, so that running test.py only outputs the lines in print statements, and the resulting debug.log file contains both the DEBUG logs and the print lines?

Answer 1

Well, I can make it work, but I don't yet know whether there are any repercussions due to it. Perhaps others will be able to point out any potential pitfalls, such as multithreading.

You can set sys.stdout to any file-like object that you like. This would include the file to which your logging.FileHandler() is writing. Try this:

fh = logging.FileHandler('debug.log')
fh.setLevel(logging.DEBUG)

old_stdout = sys.stdout    # in case you want to restore later
sys.stdout = fh.stream     # the file to which fh writes

And you can remove the code that deals with sh that is hooked up to stdout.

Answer 2

I don't think you want ALL stdout output going to log file.

What you could do is set the logging level of the console handler to logging.INFO and the logging level of the file handler to logging.DEBUG. Then replace your print statements with calls to logging.info. This way only info messages and above will be output to the console.

Something like this:

import logging
import sys

logger = logging.getLogger(__name__)

console_handler = logging.StreamHandler(sys.stdout)
file_handler = logging.FileHandler("debug.log")
console_handler.setLevel(logging.INFO)
file_handler.setLevel(logging.DEBUG)

console_formatter = logging.Formatter('%(message)s')
file_formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

console_handler.setFormatter(console_formatter)
file_handler.setFormatter(file_formatter)

logger.addHandler(console_handler)
logger.addHandler(file_handler)
logger.setLevel(logging.DEBUG) #set root logging level to DEBUG

if __name__ == "__main__":
    x = 4
    y = 5
    logger.debug("X: %s", x)
    logger.debug("Y: %s", y)
    logger.info("x is {}".format(x))
    logger.info("y is {}".format(y))
    logger.info("x * y = {}".format(x * y))
    logger.info("x^y = {}".format(x ** y))

Demo

Answer 3

If you really want all output to stdout to end up in the log file, see e.g. mhawke's answer, as well as the linked questions and answers.

However, if you are really just interested in the output from your own print() calls, then I would replace all of those by Logger.log() calls, using a custom logging level. That gives you fine-grained control over what happens.

Below, I define a custom log level with a value higher than logging.CRITICAL, so our console output is always printed, even if the logger's level is CRITICAL. See docs.

Here's a minimal implementation, based on the OP's example:

import sys
import logging

# define a custom log level with a value higher than CRITICAL
CUSTOM_LEVEL = 100

# dedicated formatter that just prints the unformatted message
# (actually this is the default behavior, but we make it explicit here)
# See docs: https://docs.python.org/3/library/logging.html#logging.Formatter
console_formatter = logging.Formatter('%(message)s')

# your basic console stream handler
console_handler = logging.StreamHandler(sys.stdout)
console_handler.setFormatter(console_formatter)

# only use this handler for our custom level messages (highest level)
console_handler.setLevel(CUSTOM_LEVEL)

# your basic file formatter and file handler
file_formatter = logging.Formatter(
    '%(asctime)s - %(name)s - %(levelname)s - %(message)s')
file_handler = logging.FileHandler('debug.log')
file_handler.setFormatter(file_formatter)
file_handler.setLevel(logging.DEBUG)

# use a module logger instead of the root logger
logger = logging.getLogger(__name__)

# add the handlers
logger.addHandler(console_handler)
logger.addHandler(file_handler)

# include messages with level DEBUG and higher
logger.setLevel(logging.DEBUG)

# NOW, instead of using print(), we use logger.log() with our CUSTOM_LEVEL
x = 4
y = 5
logger.debug(f'X: {x}')
logger.debug(f'Y: {y}')
logger.log(CUSTOM_LEVEL, f'x is {x}')
logger.log(CUSTOM_LEVEL, f'y is {y}')
logger.log(CUSTOM_LEVEL, f'x * y = {x*y}')
logger.log(CUSTOM_LEVEL, f'x^y = {x**y}')