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

Solution

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

Comments

[Jak]

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]

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]

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.