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?

Extravasation

I am not sure what exactly you are trying to accomplish, you need to clarify your desires, and give a small sample line of code and give an expected logging output for it. (ie: do a simple log.info('message') and then say what you want to go to console, what you want to go to the file.) How do you want to use these multiple loggers? it seems redundant, you only need 1 logger and you can have 2 handlers.... – Benita

obviously, I'm trying to avoid duplicate output. I consider my code sample to be clear in terms of how i want to configure my logging. – Extravasation

It if was so obvious, and if it was so clear, I wouldn't be asking. You have just dumped your code here, with little explanation of anything beyond it, and have pretty much just said "the code here is working exactly as it should, but I want it not to... what should I do?" Well... if you don't tell me what you are trying to do exactly, or how you are doing it.. It is going to be hard to help you. – Benita

2 major module loggers are enabled, they're both supposed to log to the console aswell as a file. – Extravasation

Answer 1

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.

Extravasation

this also seems to happen when logging.info or one of it's siblings is called – Extravasation

As documented, logging.info() etc. call basicConfig(), which will add a console handler if no handlers are present. These module-level functions are not meant to be intermixed with other configuration mechanisms - they're for the simplest usages. – Bingaman

Yup. @ToonAlfrink, this solution helped me the most. Adding a stream handler (and then the formatter to that handler) was the solution I needed. In my case I needed Logger.propogate = False as well. Thank you! – Transonic

I understand why you had double logging, but what did you do to solve your issue? Did you stop calling logging.getLogger all over the place? – Kempis

Answer 2

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

Note: Your logger must have a name using a non-empty string, getLogger('my name')

When it hits the child, it won't hit the parent afterwards.
Here is some documentation about this behavior.

Mysticism

In fact, the child loggers have no handlers and pass up their message for the parents to handle. – Extravasation

Even if they have a handler, it's still the same behavior – Mysticism

One important note: On py36 at least, for this .propagate=False to work, your logger must have a name using a non-empty string, so .getLogger() won't work, neither will .getLogger(''). It's got to be .getLogger('my name'). – Scut

Thank you, this is the correct answer for my case – Juxon

If you're configuring logging from a config file, you can also set the value of propagate in the file, as opposed to in code. It is a property of a specific logger (say "logger_abc"), so, under the section for that logger - say [logger_abc] - you add a line: propagate=0. The values are 0 and 1, instead of False and True, that's just how the config is parsed. – Secco

Works, but if you use caplog with pytest will fail your tests. – Haymo

Answer 3

for python 2.7

logging.handlers.pop()

Reference by user "radtek": Python Logging - Messages appearing twice

Ingratiating