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?

Edytheee

You are doing it wrong. Your modules should not define any handlers nor set the logging levels. Only the main executable should setup the handlers and the levels to be used... this simplifies everything since after you do this there's always just one handler for that file and there is no chance for that error to occur. – Jerrelljerri

The with if not len(logger.handlers): I ensure there is only 1 handler. What's a better way to do this? – Edytheee

No you do not. Because module1 and module2 have different names, which means that the loggers returned by getLogger are different and hence you are adding one handler for module1 and one for module2. So, sure a single logger does not have more than one handler, but you do have two handlers using the same file and this causes the error you see. – Jerrelljerri

I see, makes sense. So what's the best way to resolve it so I can easily call the routine and import it to the different modules? – Edytheee

There is no need for importing it. I've wrote an answer describing the typical logging setup that works in most situations. The module1 and module2 should only import the logging module and get their loggers via logging.getLogger(__name__). Everything else regarding configuration of the logging output is handled from the executable. This makes sense because it's the guy that launches the application that should be able to decide where to log something and at which level, not the module itself! – Jerrelljerri

great, let me try that – Edytheee

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.

Jerrelljerri

Can you confirm that it's necessary to set the log level again in each module, otherwise it will be set to default of logging.WARNING? – Edytheee

@nickpick Ah, sorry I forgot to add: you can just set the level of the root logger. I'll edit this in the answer. – Jerrelljerri

@nickpick Take a llok at the documentation for setLevel. It says that by default the root logger is set at WARNING, while other loggers are by default at NOTSET. When a logger is at level NOTSET the delegation to the parent logger takes place, that's why if you decide to add the handlers directly to the two module loggers then you have to modify their level, while if you add them to the root logger you should not set their level. – Jerrelljerri

I added the handlers with their respective levels to the root logger, but still need to set the level in the modules. – Edytheee

@nickpick you are probably doing something wrong. But I cannot tell without knowing exactly what you are doing. Can you edit your question to show precisely how is your current setup, and describe what happens (or does not happen) when you do not set the levels? – Jerrelljerri

The code I use is open source: www.github.com/dickreuter/poker. In main.py I put the logger as you said and I then have different modules such as /tables_analyser/base.py or /decisionmaker/decisionmaker.py. It works now but I just wonder why I have to set the level in all the modules. Maybe in main.py I don't set it properly for the root? – Edytheee

I didn't set root = logging.getLogger() root.setLevel(logging.DEBUG) in the root. Now I understand. Thanks. Is there any way to limit how deep the logging goes so that the python modules that I didn't write myself don't output logging? – Edytheee

@nickpick If those module follow the same structure you can simply set the level you want for them. For example: if my application uses the pika package, I can just put logging.getLogger('pika').setLevel(logging.WARNING). Now all messages sent to the pika logger will be filtered according to that level. – Jerrelljerri

where is this main executable where handlers need to be defined – Papp

@Papp The main executable is whatever actually runs the code. The first task of the executable should be to configure logging by either configuring them manually or using something like logging.config.dictConfig which is certainly simpler than defining everything manually – Jerrelljerri