ToonAlfrink ToonAlfrink - 2 months ago 8
Python Question

duplicate output in simple python logging configuration

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

I figured this out, thanks Paco for pointing me in the right direction

it turns out that when getLogger is called, handlers are added to it:

>>> print(effectivehandlers(logger))
[<logging.StreamHandler object at 0x305ad90>, <logging.FileHandler object at 0x305ae10>]
>>> logging.getLogger(name) #the same logger
<logging.Logger object at 0x7fa08fb9b2d0>
>>> print(effectivehandlers(logger))
[<logging.StreamHandler object at 0x305ad90>, <logging.FileHandler object at 0x305ae10>, <logging.StreamHandler object at 0x305ad90>, <logging.FileHandler object at 0x305ae10>]

Now, both the child and the parent have the same handlers. Hence duplicate outputs.

Comments