Python Logging Multiple Files

Question

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

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 output:

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 master.log:

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 the 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 its called. There should only be 5 entries in the slave.log file, but each time slave.py is called the logger outputs to every file Handler!

Thanks, Jak

slaveLog is a global object and you call addHandler each time in runMain() — pkit
– pkit, Commented Feb 29, 2012 at 13:40
Thanks, I've worked around it using: "if not len(slaveLog.handlers):" before adding the fileHandler. I was under the (mistaken) impression that the logging module wouldn't add the same fileHandler multiple times. — Jak
– Jak, Commented Feb 29, 2012 at 15:19

pkit · Accepted Answer · 2012-02-29 13:44:09Z

6

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

answered Feb 29, 2012 at 13:44

pkit

8,3798 gold badges38 silver badges37 bronze badges

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

3 Comments

Jak Over a year ago

Thanks for your reply :-) I thought that the logger module won't add an already existing Handler? Because its the same [name] each time it is called I don't get why it keeps adding another Handler. I can even run the removeHandler() function but it doesn't remove anything.

Vinay Sajip Over a year ago

As pkit says, you're doing it wrong. You should only configure logging (add handlers, set levels etc.) in one place. See this post: eric.themoritzfamily.com/learning-python-logging.html

Jak Over a year ago

Thanks I have it now :-) The slave.py sometimes gets called as a script by itself, so in that scenario I need to have the logging configured in slave.py. But slave.py also gets called by master.py multiple times, in which case the logging is already configured and therefore slave.py adds the same fileHandler multiple times, thus giving the error.

wcc526 · Accepted Answer · 2015-10-31 14:10:35Z

#!/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'd better to config the logging format in the main function.

Collectives™ on Stack Overflow

Python Logging Multiple Files

2 Answers 2

3 Comments

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

2 Answers 2

3 Comments

Comments

Your Answer

Sign up or log in

Post as a guest

Related