How to log into different files properly in Python?

Question

I have a logger configuration class below, my_logger.py:

def my_logger(module_name, log_file):
    logger = logging.getLogger(module_name)
    logger.setLevel(logging.DEBUG)

    # Create handlers
    c_handler = logging.StreamHandler()
    f_handler = logging.handlers.RotatingFileHandler(filename=log_file)
    c_handler.setLevel(logging.DEBUG)
    f_handler.setLevel(logging.DEBUG)

    # Create formatters and add it to handlers
    c_format = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(lineno)d - %(message)s')
    f_format = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(lineno)d - %(message)s')
    c_handler.setFormatter(c_format)
    f_handler.setFormatter(f_format)

    # Add handlers to the logger
    logger.addHandler(c_handler)
    logger.addHandler(f_handler)

    return logger

This my_logger.py is under the package root directory:

my_package:
    my_logger.py
    test.py
    api/api.py
    logs/

Then in my test.py:

abspath = os.path.abspath(os.path.dirname(__file__))

logger_info = logger.my_logger("test_info", os.path.join(abspath,"../logs/info.log"))
logger_debug = logger.my_logger("test_debug", os.path.join(abspath,"../logs/debug.log"))
logger_error = logger.my_logger("test_error", os.path.join(abspath,"../logs/error.log"))

logger_info.info('Info test ...')
logger_debug.debug('Debug test ...')
logger_error.error('Error test ...')

I want to debugging to debug.log, info to info.log and error to error.log.

For each file that I want to log, I need to add the following 3 lines to each file:

logger_info = logger.my_logger(module_info, os.path.join(abspath,"../logs/info.log"))
logger_debug = logger.my_logger(module_debug, os.path.join(abspath,"../logs/debug.log"))
logger_error = logger.my_logger(module_error, os.path.join(abspath,"../logs/error.log"))

Is this normal practice? I want all log messages from all modules to go into the same 3 files under logs/.

bkakilli · Accepted Answer · 2020-12-04T22:16:08.433

Short answer

To achieve exactly what you described, you need 3 handlers (which you have in your example), and set their default level to the corresponding level at the top. No need to set the handler's levels separately.

import logging
from logging import handlers

def my_logger(module_name, log_file, level):
    logger = logging.getLogger(module_name)
    logger.setLevel(level)

    # Create handlers
    c_handler = logging.StreamHandler()
    f_handler = handlers.RotatingFileHandler(filename=log_file)

    # Create formatters and add it to handlers
    c_format = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(lineno)d - %(message)s')
    f_format = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(lineno)d - %(message)s')
    c_handler.setFormatter(c_format)
    f_handler.setFormatter(f_format)

    # Add handlers to the logger
    logger.addHandler(c_handler)
    logger.addHandler(f_handler)

    return logger

if __name__ == "__main__":
    logger_info = my_logger("test_info", "info.log", logging.INFO)
    logger_debug = my_logger("test_debug", "debug.log", logging.DEBUG)
    logger_error = my_logger("test_error", "error.log", logging.ERROR)

    logger_info.info('Info test ...')
    logger_debug.debug('Debug test ...')
    logger_error.error('Error test ...')

Output:

python test_logger2.py 
2020-12-04 16:57:00,771 - test_info - INFO - 29 - Info test ...
2020-12-04 16:57:00,771 - test_debug - DEBUG - 30 - Debug test ...
2020-12-04 16:57:00,771 - test_error - ERROR - 31 - Error test ...

cat info.log 
2020-12-04 16:57:00,771 - test_info - INFO - 29 - Info test ...

cat debug.log 
2020-12-04 16:57:00,771 - test_debug - DEBUG - 30 - Debug test ...

cat error.log 
2020-12-04 16:57:00,771 - test_error - ERROR - 31 - Error test ...

Long answer:

Why 3 copies?
You are calling your my_logger function 3 times, and each time you call it a new file handler as well as a NEW stream handler added to the logger. That's why you see 3 copies on your console (3 stream handlers). Plus all your handlers are set to DEBUG level. That's why all three logger prints out any log that you have given. You don't want a ERROR handler to process/print logs at DEBUG/INFO levels, so you should set its level to ERROR.
I don't think this is the standard approach for logging. You should instead have single logger with 4 handlers (stream, file_debug, file_info, file_error). Additionally, a debug log file should include all logs, and an info log file should include info logs and error logs. Details below.

import logging
from logging import handlers

def main():

    logger = logging.getLogger()
    c_format = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(lineno)d - %(message)s')

    # You need to set the default level to the lowest (DEBUG)
    logger.setLevel(logging.DEBUG)

    c_handler = logging.StreamHandler()
    c_handler.setLevel(logging.DEBUG)
    c_handler.setFormatter(c_format)

    f1_handler = handlers.RotatingFileHandler("debug.log")
    f1_handler.setLevel(logging.DEBUG)
    f1_handler.setFormatter(c_format)

    f2_handler = logging.handlers.RotatingFileHandler("info.log")
    f2_handler.setLevel(logging.INFO)
    f2_handler.setFormatter(c_format)

    f3_handler = logging.handlers.RotatingFileHandler("error.log")
    f3_handler.setLevel(logging.ERROR)
    f3_handler.setFormatter(c_format)

    logger.addHandler(c_handler)
    logger.addHandler(f1_handler)
    logger.addHandler(f2_handler)
    logger.addHandler(f3_handler)

    logger.debug("A debug line")
    logger.info("An info line")
    logger.error("An error line")

if __name__ == "__main__":
    main()

The output is :

python test_logger.py 
2020-12-04 16:48:56,247 - root - DEBUG - 32 - A debug line
2020-12-04 16:48:56,248 - root - INFO - 33 - An info line
2020-12-04 16:48:56,248 - root - ERROR - 34 - An error line

cat debug.log 
2020-12-04 16:49:06,673 - root - DEBUG - 32 - A debug line
2020-12-04 16:49:06,673 - root - INFO - 33 - An info line
2020-12-04 16:49:06,673 - root - ERROR - 34 - An error line

cat info.log 
2020-12-04 16:49:06,673 - root - INFO - 33 - An info line
2020-12-04 16:49:06,673 - root - ERROR - 34 - An error line

cat error.log 
2020-12-04 16:49:06,673 - root - ERROR - 34 - An error line

Here you see your debug.log file also contains the logs from other levels, and your info.log file contain error logs too. Because that's the whole rationale behind the log levels. The lower level should also keep track of the logs of higher levels (DEBUG < INFO < WARNING < ERROR). That's why what you want is not a standard way of doing it, but can perfectly be achieved as described in the short answer.

@bkailli, is there a way that I can conveniently turn on/off all logs? For example, in development mode, I want all logs on, and in production, I want all log off. Is there a way to do it? Would this make sense? — marlon, Dec 04 '20 at 22:31
You should log the things that you want to see in with debug (logger.debug(...)). If you initialize your logger with something higher then DEBUG level in production, say INFO, then those logs won't be processed. But you will still see INFO and above. If you want to completely get rid of all logs, then simply don't add any handlers to your logger in your production code. — bkakilli, Dec 04 '20 at 23:16
Should I change the default 'level', or the handler's 'level' in production? Should I use a configuration file to control the log level in practice? — marlon, Dec 04 '20 at 23:36
For the first case, only the default level should suffice. For the latter it doesn't matter since there will be no handlers anyway. Setting it through a configuration file is an option, yes. — bkakilli, Dec 06 '20 at 00:07
For production, should I turn off the stream handler to avoid it to be printed out to terminal? I am afraid it may be slowing down the system when printing out to the screen. — marlon, Dec 07 '20 at 20:52
If no one will be looking at the logs in production, there is no point using it. Plus, if performance is a real concern, then I would not suggest using more than one handler anyway. Just one filehandler should be enough. You can always parse it afterwards to make 3 different log files from single log file. You can even use StreamIO instead of printing out to a file to reduce disk access, then periodically flushing your buffer to a file (assuming you are constrained by processing power) Check out here: https://stackoverflow.com/questions/9534245/python-logging-to-stringio-handler — bkakilli, Dec 07 '20 at 21:01
So you suggest only use a 'debug' handler to store everything and no info, warn and error? Print out to screen is useful only in development time. Right? Also, how does additional handlers impact performance? If they are very small, I just keep 4 handlers. But definitely the stream handler printing out screen I want to turn off. — marlon, Dec 07 '20 at 21:25
Please review the logging documentation first. Your debug handler will contain all logs (debug, info, error etc.) anyways. — bkakilli, Dec 07 '20 at 21:42

How to log into different files properly in Python?

1 Answers1

Short answer

Long answer: