duplicate output in simple python logging configuration

Question

I'm setting up python logging as follows:

def setup_logging():     loggers = (logging.getLogger("amcat"), logging.getLogger("scrapers"),logging.getLogger(__name__))     filename = "somefile.txt"     sys.stderr = open(filename, 'a')     handlers = (logging.StreamHandler(sys.stdout),logging.FileHandler(filename))     formatter = AmcatFormatter(date = True)      for handler in handlers:         handler.setLevel(logging.INFO)         handler.setFormatter(formatter)      for logger in loggers:         logger.propagate = False         logger.setLevel(logging.INFO)         for handler in handlers:                     logger.addHandler(handler)     logging.getLogger().handlers = [] 

2 major module loggers are enabled, they're both supposed to log to the console aswell as a file. errors are redirected to the file (ideally, errors would show in the console as well but i've yet to implement this)

Right after, i check whether things are right:

should_work = [     "amcat.scraping.scraper",     "amcat.scraping.htmltools",     "amcat.scraping.controller",     "__main__"]  loggerdict = logging.Logger.manager.loggerDict #all loggers for name, logger in loggerdict.items():     if name in should_work:         print("\nlogger: "+name)         #iterate through parents see if effective handlers are set correctly         print(effectivehandlers(logger))         #test logger         logger.info("test for {name}".format(**locals()))  def effectivehandlers(logger):     handlers = logger.handlers     while True:         logger = logger.parent         handlers.extend(logger.handlers)         if not (logger.parent and logger.propagate):             break     return handlers 

The console output:

logger: __main__ [<logging.StreamHandler object at 0x3425d50>, <logging.FileHandler object at 0x3425dd0>] [2013-10-24 10:27:30 daily.py:133 INFO] test for __main__  logger: amcat.scraping.controller [<logging.StreamHandler object at 0x3425d50>, <logging.FileHandler object at 0x3425dd0>] [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.controller [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.controller  logger: amcat.scraping.htmltools [<logging.StreamHandler object at 0x3425d50>, <logging.FileHandler object at 0x3425dd0>] [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.htmltools [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.htmltools  logger: amcat.scraping.scraper [<logging.StreamHandler object at 0x3425d50>, <logging.FileHandler object at 0x3425dd0>] [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.scraper [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.scraper 

And here's the file output:

[2013-10-24 10:27:30 daily.py:133 INFO] test for __main__ [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.controller [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.controller [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.htmltools [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.htmltools [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.scraper [2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.scraper 

As you can see, the output is double, despite having disabled propagation and making sure no duplicate handlers are present. Where does this go wrong?

Answer 1

Basically, when one of your child logger displays a message, it goes backwards in the hierarchy, and the parents are also logging the same thing.

To cancel that behavior, you can add this:

logger.propagate = False 

When it hits the child, it won't hit the parent afterwards.

Here is some documentation about this behavior.