What could cause the logging module to log a recor

Question

I have a multi-threaded Python application that makes use of the built in logging module. To control the logging levels and make it easier to swap the StreamHandler with a FileHandler in the future, I have created a common helper function called by each module to create an identical logger (other than its name).

How should I go about trouble shooting this issue?

Key Points

1. Each module in the project has its own logger instance.
2. The sample output is generated by a single call to a logger (self._logger.info("Logger Setup"))
3. I have tried including the current thread name (threading.Thread.getName()) and it confirms that the same thread is calling causing the multiple logs.

Logger Creation - Now working

import logging
import sys
def createSystemLogHandler(logger):
    # This is now called once at the logger's root 
    ch = logging.StreamHandler(sys.stdout) # Normal output is to stderr which doesn't show up on Window's CMD
    format = logging.Formatter('%(asctime)s - %(levelname)s - %(name)s - %(message)s')
    ch.setFormatter(format)
    logger.addHandler(ch)
    return logger

def configureSystemLogger(name='', level=logging.WARNING):
        logger = logging.getLogger(name)
        logger.setLevel(level)
        logger.info("Logger Setup")
        return logger

Sample Output

2012-04-25 21:59:40,720 - INFO - HW_MGR - Logger Setup
2012-04-25 21:59:40,720 - INFO - HW_MGR - Logger Setup
2012-04-25 21:59:40,720 - INFO - HW_MGR - Logger Setup
2012-04-25 21:59:40,720 - INFO - HW_MGR - Logger Setup
2012-04-25 21:59:40,720 - INFO - HW_MGR - Logger Setup

Answer 1

My guess is that you've got multiple handlers (ie, one message is being emitted multiple times; but on re-reading your question, it looks like you already knew that). To debug that, try:

• Looking at logging.getLogger("").handlers (ie, the handlers on the root logger)
• Checking your calls to addHandler()
• Brandon Rhode's logging_tree module
• Use pdb to trace a log message's lifecycle (ie, put a breakpoint just before a call to self._logger.info(…), then step into that function).