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?

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. — Bakuriu
– Bakuriu, Commented Nov 8, 2016 at 19:48
The with if not len(logger.handlers): I ensure there is only 1 handler. What's a better way to do this? — Nickpick
– Nickpick, Commented Nov 8, 2016 at 19:49
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. — Bakuriu
– Bakuriu, Commented Nov 8, 2016 at 19:52
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? — Nickpick
– Nickpick, Commented Nov 8, 2016 at 19:53
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! — Bakuriu
– Bakuriu, Commented Nov 8, 2016 at 20:07

Bakuriu · Accepted Answer · 2016-11-09 07:24:39Z

25

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.

edited Nov 9, 2016 at 7:24

answered Nov 8, 2016 at 20:05

Bakuriu

103k23 gold badges208 silver badges236 bronze badges

Sign up to request clarification or add additional context in comments.

10 Comments

Nickpick Over a year ago

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?

Bakuriu Over a year ago

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

Bakuriu Over a year ago

@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.

Nickpick Over a year ago

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

Bakuriu Over a year ago

@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.

|

Collectives™ on Stack Overflow

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

1 Answer 1

10 Comments

Your Answer

Linked

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

10 Comments

Your Answer

Sign up or log in

Post as a guest

Linked

Related