30

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?

4
  • 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....
    – Inbar Rose
    Oct 24, 2013 at 8:53
  • 3
    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. Oct 24, 2013 at 9:08
  • 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.
    – Inbar Rose
    Oct 24, 2013 at 9:14
  • 1
    2 major module loggers are enabled, they're both supposed to log to the console aswell as a file. Oct 24, 2013 at 9:22

3 Answers 3

97

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.

5
  • In fact, the child loggers have no handlers and pass up their message for the parents to handle. Oct 24, 2013 at 9:03
  • 2
    Even if they have a handler, it's still the same behavior
    – Paco
    Oct 24, 2013 at 9:04
  • 4
    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').
    – kakyo
    May 14, 2018 at 18:54
  • Thank you, this is the correct answer for my case
    – HCLivess
    Jul 13, 2022 at 23:43
  • 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. Aug 2, 2022 at 9:39
14

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.

4
  • 1
    this also seems to happen when logging.info or one of it's siblings is called Oct 24, 2013 at 9:29
  • 3
    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. Oct 25, 2013 at 6:48
  • 1
    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! Dec 23, 2014 at 1:58
  • 12
    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?
    – Jay
    Aug 12, 2015 at 18:36
0

for python 2.7

logging.handlers.pop()

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

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.