Python logs multiple files

Question

I have a problem with the Python logging module, I'm not sure I'm doing something stupid, but I have two Python scripts: one (master.py) that calls the other (slave.py). They are both logged to separate the log files, but the second script (slave.py) called is the log recursively recursive!

Can anyone see what I'm doing wrong here?

Here is my code:

# master.py import sys import logging import slave masterLog = logging.getLogger('master') masterLog.setLevel(logging.DEBUG) masterHandler = logging.FileHandler('master.log') formatter = logging.Formatter('%(levelname)s: %(asctime)s %(funcName)s(%(lineno)d) -- %(message)s', datefmt = '%Y-%m-%d %H:%M:%S') masterHandler.setFormatter(formatter) masterLog.addHandler(masterHandler) masterLog.info('This is masterLog running on master.py') print 'master.py has: ', len(masterLog.handlers), 'handlers' for i in range(1,6): masterLog.info('Running slave %s' % i) slave.runMain() 

---

 # slave.py import sys import logging def runMain(): slaveLog = logging.getLogger('slave') slaveLog.setLevel(logging.DEBUG) slaveHandler = logging.FileHandler('slave.log') formatter = logging.Formatter('%(levelname)s: %(asctime)s %(funcName)s(%(lineno)d) -- %(message)s', datefmt = '%Y-%m-%d %H:%M:%S') slaveHandler.setFormatter(formatter) slaveLog.addHandler(slaveHandler) slaveLog.info('This is slaveLog running on slave.py') print 'slave.py has: ', len(slaveLog.handlers), 'handlers' if __name__ == '__main__': runMain() 

Here is the result:

 master.py has: 1 handlers slave.py has: 1 handlers slave.py has: 2 handlers slave.py has: 3 handlers slave.py has: 4 handlers slave.py has: 5 handlers 

And the .log master:

 INFO: 2012-02-29 13:26:49 <module>(13) -- This is masterLog running on master.py INFO: 2012-02-29 13:26:49 <module>(17) -- Running slave 1 INFO: 2012-02-29 13:26:49 <module>(17) -- Running slave 2 INFO: 2012-02-29 13:26:49 <module>(17) -- Running slave 3 INFO: 2012-02-29 13:26:49 <module>(17) -- Running slave 4 INFO: 2012-02-29 13:26:49 <module>(17) -- Running slave 5 

And slave.log:

 INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py INFO: 2012-02-29 13:26:49 runMain(13) -- This is slaveLog running on slave.py 

The slave script seems to add a new file handler each time it is called. There should be only 5 entries in the slave.log file, but every time slave.py is called by the log output for each file handler!

Thanks Jak

Answer 1

logging.getLogger([name]) always returns the same object (global object), and you call addHandler on it every time you call runMain.

Answer 2

 #!/usr/bin/env python # -*- coding: utf-8 -*- import logging import logging.handlers from logging.config import dictConfig logger = logging.getLogger(__name__) DEFAULT_LOGGING = { 'version': 1, 'disable_existing_loggers': False, } def configure_logging(logfile_path): """ Initialize logging defaults for Project. :param logfile_path: logfile used to the logfile :type logfile_path: string This function does: - Assign INFO and DEBUG level to logger file handler and console handler """ dictConfig(DEFAULT_LOGGING) default_formatter = logging.Formatter( "[%(asctime)s] [%(levelname)s] [%(name)s] [%(funcName)s():%(lineno)s] [PID:%(process)d TID:%(thread)d] %(message)s", "%d/%m/%Y %H:%M:%S") file_handler = logging.handlers.RotatingFileHandler(logfile_path, maxBytes=10485760,backupCount=300, encoding='utf-8') file_handler.setLevel(logging.INFO) console_handler = logging.StreamHandler() console_handler.setLevel(logging.DEBUG) file_handler.setFormatter(default_formatter) console_handler.setFormatter(default_formatter) logging.root.setLevel(logging.DEBUG) logging.root.addHandler(file_handler) logging.root.addHandler(console_handler) [31/10/2015 22:00:33] [DEBUG] [yourmodulename] [yourfunction_name():9] [PID:61314 TID:140735248744448] this is logger infomation from hello module 

I think you better set up the logging format in the main function.