1
votes

I'm seeing extra logging messages after I've imported a module I need to use. I'm trying to work out the correct way to stop this happening. The following code shows the issue best:

import os
import logging
import flickrapi

class someObject:
    def __init__(self):
        self.value = 1
        logger = logging.getLogger(__name__)
        print logger.handlers
        logger.info("value = " + str(self.value))

def main():
    # Set up logging
    logger = logging.getLogger(__name__)
    logger.setLevel(logging.DEBUG)
    formatter = logging.Formatter('[%(asctime)-15s] %(name)-8s %(levelname)-6s %message)s')
    fh = logging.FileHandler(os.path.splitext(os.path.basename(__file__))[0]+".log")
    fh.setLevel(logging.DEBUG)
    fh.setFormatter(formatter)
    logger.addHandler(fh)
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)
    ch.setFormatter(formatter)
    logger.addHandler(ch)
    logger.debug("Debug message")
    logger.info("Info message")

    thingy = someObject()

if __name__ == "__main__":
    main()

With the flickrapi import I see the following output:

DEBUG:__main__:Debug message
[2013-05-03 12:10:47,755] __main__ INFO   Info message
INFO:__main__:Info message
[<logging.FileHandler instance at 0x1676dd0>, <logging.StreamHandler instance at 0x1676ea8>]
[2013-05-03 12:10:47,755] __main__ INFO   value = 1
INFO:__main__:value = 1

With the flickrapi import removed I see the correct output:

[2013-05-03 12:10:47,755] __main__ INFO   Info message
[<logging.FileHandler instance at 0x1676dd0>, <logging.StreamHandler instance at 0x1676ea8>]
[2013-05-03 12:10:47,755] __main__ INFO   value = 1

This is my first time of using logging and it's got me a little stumped. I've read the documentation a couple of times but I think I'm missing something in my understanding.

Looking at logging.Logger.manager.loggerDict, there are other loggers but each of their .handlers is empty. The __main__ logger only has the two handlers I've added so where do these messages come from?

Any pointers as to how I can solve this would be much appreciated as I've hit a wall.

Thanks

1

1 Answers

3
votes

This is a bug in the flickrapi library you are using. It is calling logging.basicConfig() in it's __init__.py which is the wrong thing to do for a library since it adds a StreamHandler defaulting to stderr to the root logger.

You should probably open a bug report with the author. There is a HOWTO in the python logging docs on how libraries should configure logging.

To work around this issue until the bug is fixed you should be able to do the following:

# at the top of your module before doing anything else
import flickrapi
import logging
try:
    logging.root.handlers.pop()
except IndexError:
    # once the bug is fixed in the library the handlers list will be empty - so we need to catch this error
    pass