Python logging in interactive sessions

I am trying to implement logging in my Python 2.7 applications and have found it very useful. However, I have noticed that when running Python interactively each logging message prints multiple times. The number of times the message is printed is the same as the number of times I have previously run the script, so it seems that the logger is not being cleaned up properly at the end of the script (I would guess). Consider the following example:

import sys
import logging

def main(argv=None):

    log = logging.getLogger('test')
    log.setLevel(logging.DEBUG)

    console_handler = logging.StreamHandler()
    console_handler.setFormatter(logging.Formatter("%(message)s"))
    log.addHandler(console_handler)

    log.info('Starting something...')
    log.info('Doing something...')
    log.info('Finished something.')

    logging.shutdown()

if __name__=='__main__':
    sys.e开发者_开发百科xit(main(sys.argv[1:]))

Typing

>>> import file.py
>>> file.main()

yields the following:

Starting something...
Doing something...
Finished something.

Then typing file.main() a second time yields:

Starting something...
Starting something...
Doing something...
Doing something...
Finished something.
Finished something.

Repeating a third time would give three or each message and so on. Does anyone know why this is happening - is this the expected behaviour of the logging module and, if so, how can I change this? The above script only prints one of each message if run as a script (python file.py), as expected.

Yes, you are creating and reusing a single instance of your logger. Each handler added to that logger is also logging a message.

You probably want logging setup to be at the module level or in a separate function so you only run it once.

Maybe something like this:

import atexit
import sys
import logging

log = logging.getLogger('test')
log.setLevel(logging.DEBUG)

console_handler = logging.StreamHandler()
console_handler.setFormatter(logging.Formatter("%(message)s"))
log.addHandler(console_handler)

def shutdown_logging():
    logging.shutdown()    

atexit.register(shutdown_logging)

def main(argv=None):
    log.info('Starting something...')
    log.info('Doing something...')
    log.info('Finished something.')


if __name__=='__main__':
    sys.exit(main(sys.argv[1:]))

Try this as a workaround:

if len(logging.root.handlers) == 0:
     log.add_handler(console_handler)

The logging module uses a globally static logger object that persists across your session when you are in the interpreter. So every time you call add_handler you're adding a brand new stream handler but not removing the old one. Logging just iterates through its handlers and sends the output to each, so you have a new copy of the same thing going to the console every time you run.

You could delete all handlers every time you reload your configuration, in your case before calling file.main():

file.logging.getLogger('test').handlers = []

Note (subjective):

As @stderr wrote, it's encouraged to define your loggers at module level. However, I think it's also a good practice to set them up at the application entry point, so here I would only add the handlers after the if __name__=='__main__', or in your case, in your (I)Python console. That way, importing the module does not create all sorts of handlers, but those are only created by the person who chooses to execute some functions of your module.

Here's an alternative to @beer_monk's solution, which will work even if you've touched the root handler somewhere else. I've used __name__ instead of 'test' here so that it's easier to reuse the code in other modules, perhaps by making this into a function that takes __name__ as an argument.

if not __name__ in logging.Logger.manager.loggerDict:
    new_logger = logging.getLogger(__name__)
    new_logger.setLevel(logging.DEBUG)

    console_handler = logging.StreamHandler()
    console_handler.setFormatter(logging.Formatter("%(message)s"))
    new_logger.addHandler(console_handler)
log = logging.getLogger(__name__)