Python logging in several modules outputs twice

Question

I'm not very familiar with python logging and I am trying to get it to log output to the console. I've gotten it to work but it seems that the output is seen twice in the console and I'm not sure why. I've looked at the other questions asked here about similar situations but I could not find anything that helped me.

I have three modules, lets call them ma, mb, mc and a main. The main imports these 3 modules and calls their functions.

In each module I set up a logger like so:

ma.py

import logging
logger = logging.getLogger('test.ma') #test.mb for mb.py/test.mc for mc.py
logger.setLevel(logging.DEBUG)

console_log = logging.StreamHandler()
console_log.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(message)s')
console_log.setFormatter(formatter)
logger.addHandler(console_log)
...
...
#right before the end of each module, after I'm finished logging what I need.
logger.removeHandler(console_log)

mb.py

import logging
logger = logging.getLogger('test.mb')
logger.setLevel(logging.DEBUG)

console_log = logging.StreamHandler()
console_log.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(message)s')
console_log.setFormatter(formatter)
logger.addHandler(console_log)
...
...
#end of file
logger.removeHandler(console_log)

mc.py

import logging
logger = logging.getLogger('test.mc')
logger.setLevel(logging.DEBUG)

console_log = logging.StreamHandler()
console_log.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(message)s')
console_log.setFormatter(formatter)
logger.addHandler(console_log)
...
...
#end of file
logger.removeHandler(console_log)

The main problem I'm having is that output is printing twice and for some parts of the program it is not formatted. Any help would appreciated, thanks!

Answer 1

A better approach to using a global logger is to use a function that wraps the call to logging.getLogger:

import logging

def get_logger(name):
    logger = logging.getLogger(name)
    if not logger.handlers:
        # Prevent logging from propagating to the root logger
        logger.propagate = 0
        console = logging.StreamHandler()
        logger.addHandler(console)
        formatter = logging.Formatter('%(asctime)s - %(name)s - %(message)s')
        console.setFormatter(formatter)
    return logger

def main():
    logger = get_logger(__name__)
    logger.setLevel(logging.DEBUG)
    logger.info("This is an info message")
    logger.error("This is an error message")
    logger.debug("This is a debug message")

if __name__ == '__main__':
    main()

Output

2017-03-09 12:02:41,083 - __main__ - This is an info message
2017-03-09 12:02:41,083 - __main__ - This is an error message
2017-03-09 12:02:41,083 - __main__ - This is a debug message

Note: Using a function also allows us to set logger.propagate to False to prevent log messages from being sent to the root logger. This is almost certainly the cause of the duplicated output you are seeing.

Update: After calling get_logger, the desired level must be set by calling logger.setLevel. If this is not done, then only error messages will be seen.