Using python logging from multiple modules with writing to a file and RotatingFileHandler

Question

I'm using the below module to log events in my modules. I call it as follows:

module 1

from tools.debug_logger import debug_logger
self.logger = debug_logger().start_logger('module1')
self.logger.debug("Top left corner found")

module2:

from tools.debug_logger import debug_logger
self.logger = debug_logger().start_logger('module2')
self.logger.debug("Top left corner found")

and here the file /tools/debug_logger.py

import logging, logging.handlers
import sys
class debug_logger(object):
    def start_logger(self,name):
        logger = logging.getLogger(name)
        logger.setLevel(logging.DEBUG)
        if not len(logger.handlers):
            fh = logging.handlers.RotatingFileHandler('log/pokerprogram.log', maxBytes=1000000, backupCount=10)
            fh.setLevel(logging.DEBUG)
            fh2 = logging.handlers.RotatingFileHandler('log/pokerprogram_info_only.log', maxBytes=1000000, backupCount=5)
            fh2.setLevel(logging.INFO)
            er = logging.handlers.RotatingFileHandler('log/errors.log', maxBytes=2000000, backupCount=2)
            er.setLevel(logging.WARNING)
            ch = logging.StreamHandler(sys.stdout)
            ch.setLevel(1)
            fh.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s'))
            fh2.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s'))
            er.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s'))
            ch.setFormatter(logging.Formatter('%(name)s - %(levelname)s - %(message)s'))
            logger.addHandler(fh)
            logger.addHandler(fh2)
            logger.addHandler(ch)
            logger.addHandler(er)
        return logger

Everything works fine and I get log files for the respective levels, but when the RotatingFileHandler is called I sometimes get an error. It is as if various instances want to do the rotation at the same time, even though I'm quite sure this shouldn't happen as I make sure there's only 1 handler with if not len(logger.handlers) as recommended here: Duplicate log output when using Python logging module.

Any suggestion what could be causing this file access violation during the rotation would be appreciated.

PermissionError: [WinError 32] The process cannot access the file because it is being used by another process: 'C:\\Users\\Nicolas\\Dropbox\\PythonProjects\\Poker\\log\\pokerprogram.log' -> 'C:\\Users\\Nicolas\\Dropbox\\PythonProjects\\Poker\\log\\pokerprogram.log.1'

I believe the permission error occur because when the rotation occurs other modules are still writing to the file.

What would be the best way to do logging from multiple modules when I write to a file and use this RotatingFileHandler? Is there any best practice?

Answer 1

I believe you are getting your logging setup wrong. The recommended way to setup logging is to not define any handlers nor logging levels into the modules, but define all the configuration in the main file.

For example in module1.py:

import logging

logger = logging.getLogger(__name__)

# use logger.info/logger.debug etc.

In module2.py you put exactly the same code:

import logging

logger = logging.getLogger(__name__)

# use logger.info/logger.debug etc.

Note that __name__ is the module name, so it will be something like package.module1 or package.module2. Using dotted names automatically creates hierarchies of loggers, so that's why it's customary to just use the __name__ of the module to get the logger.

There is no need for module1 and module2 to contain anything else related to logging. They should not decide where the logging output goes or its level, because this is something that who launches the application should control. Hence it is best handled in the main executable.

Now in your main executable you define your handlers:

import logging, logging.handlers

fh = logging.handlers.RotatingFileHandler('log/pokerprogram.log', maxBytes=1000000, backupCount=10)
fh.setLevel(logging.DEBUG)
fh2 = logging.handlers.RotatingFileHandler('log/pokerprogram_info_only.log', maxBytes=1000000, backupCount=5)
fh2.setLevel(logging.INFO)
er = logging.handlers.RotatingFileHandler('log/errors.log', maxBytes=2000000, backupCount=2)
er.setLevel(logging.WARNING)
ch = logging.StreamHandler(sys.stdout)
ch.setLevel(1)
fh.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s'))
fh2.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s'))
er.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s'))
ch.setFormatter(logging.Formatter('%(name)s - %(levelname)s - %(message)s'))

And finally you just add the handlers to the root logger and set the root logger's level to the lowest level among the handlers:

root = logging.getLogger()
root.setLevel(logging.DEBUG)
# alternatively:
# root.setLevel(min([fh.level, fh2.level, ch.level, er.level])

root.addHandler(fh)
root.addHandler(fh2)
root.addHandler(ch)
root.addHandler(er)

This works due to the hierarchical nature of loggers. When module1.logger.debug is called, if the logger has no handlers it will pass the log record to its parent logger, which will continue to do so up until the root logger, which finally uses its handlers to handle the log record.

It is necessary to also set the root logger level because it defaults to WARNING, while other loggers default to NOTSET (which causes the delegation mentioned before).

Alternatively you add the same handlers to both module loggers explicitly:

from <package> import module1, module2

module1.logger.setLevel(logging.DEBUG)
module2.logger.setLevel(logging.DEBUG)

module1.logger.addHandler(fh)
module2.logger.addHandler(fh)
module1.logger.addHandler(fh2)
module2.logger.addHandler(fh2)
module1.logger.addHandler(ch)
module2.logger.addHandler(ch)
module1.logger.addHandler(er)
module2.logger.addHandler(er)

There is no harm in adding the same handler object to multiple loggers. This makes sure that the handlers do not try to concurrently rotate the file.