日志消息使用Python Logging出现两次

I’m using Python logging, and for some reason, all of my messages are appearing twice.

I have a module to configure logging:

# BUG: It's outputting logging messages twice - not sure why - it's not the propagate setting.
def configure_logging(self, logging_file):
    self.logger = logging.getLogger("my_logger")
    self.logger.setLevel(logging.DEBUG)
    self.logger.propagate = 0
    # Format for our loglines
    formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
    # Setup console logging
    ch = logging.StreamHandler()
    ch.setLevel(logging.DEBUG)
    ch.setFormatter(formatter)
    self.logger.addHandler(ch)
    # Setup file logging as well
    fh = logging.FileHandler(LOG_FILENAME)
    fh.setLevel(logging.DEBUG)
    fh.setFormatter(formatter)
    self.logger.addHandler(fh)

Later on, I call this method to configure logging:

if __name__ == '__main__':
    tom = Boy()
    tom.configure_logging(LOG_FILENAME)
    tom.buy_ham()

And then within say, the buy_ham module, I’d call:

self.logger.info('Successfully able to write to %s' % path)

And for some reason, all the messages are appearing twice. I commented out one of the stream handlers, still the same thing. Bit of a weird one, not sure why this is happening…lol. Assuming I’ve missed something obvious.

Cheers, Victor

You are calling configure_logging twice (maybe in the __init__ method of Boy) : getLogger will return the same object, but addHandler does not check if a similar handler has already been added to the logger.

Try tracing calls to that method and eliminating one of these. Or set up a flag logging_initialized initialized to False in the __init__ method of Boy and change configure_logging to do nothing if logging_initialized is True, and to set it to True after you’ve initialized the logger.

If your program creates several Boy instances, you’ll have to change the way you do things with a global configure_logging function adding the handlers, and the Boy.configure_logging method only initializing the self.logger attribute.

Another way of solving this is by checking the handlers attribute of your logger:

logger = logging.getLogger('my_logger')
if not logger.handlers:
    # create the handlers and call logger.addHandler(logging_handler)

If you are seeing this problem and you’re not adding the handler twice then see abarnert’s answer here

From the docs:

Note: If you attach a handler to a logger and one or more of its ancestors, it may emit the same record multiple times. In general, you should not need to attach a handler to more than one logger – if you just attach it to the appropriate logger which is highest in the logger hierarchy, then it will see all events logged by all descendant loggers, provided that their propagate setting is left set to True. A common scenario is to attach handlers only to the root logger, and to let propagation take care of the rest.

So, if you want a custom handler on “test”, and you don’t want its messages also going to the root handler, the answer is simple: turn off its propagate flag:

logger.propagate = False

The handler is added each time you call from outside. Try Removeing the Handler after you finish your job:

self.logger.removeHandler(ch)

I’m a python newbie, but this seemed to work for me (Python 2.7)

while logger.handlers:
     logger.handlers.pop()

In my case I’d to set logger.propagate = False to prevent double printing.

In below code if you remove logger.propagate = False then you will see double printing.

import logging
from typing import Optional

_logger: Optional[logging.Logger] = None

def get_logger() -> logging.Logger:
    global _logger
    if _logger is None:
        raise RuntimeError('get_logger call made before logger was setup!')
    return _logger

def set_logger(name:str, level=logging.DEBUG) -> None:
    global _logger
    if _logger is not None:
        raise RuntimeError('_logger is already setup!')
    _logger = logging.getLogger(name)
    _logger.handlers.clear()
    _logger.setLevel(level)
    ch = logging.StreamHandler()
    ch.setLevel(level)
    # warnings.filterwarnings("ignore", "(Possibly )?corrupt EXIF data", UserWarning)
    ch.setFormatter(_get_formatter())
    _logger.addHandler(ch)
    _logger.propagate = False # otherwise root logger prints things again


def _get_formatter() -> logging.Formatter:
    return logging.Formatter(
        '[%(asctime)s] [%(name)s] [%(levelname)s] %(message)s')

A call to logging.debug() calls logging.basicConfig() if there are no root handlers installed. That was happening for me in a test framework where I couldn’t control the order that test cases fired. My initialization code was installing the second one. The default uses logging.BASIC_FORMAT that I didn’t want.

It seems that if you output something to the logger (accidentally) then configure it, it is too late. For example, in my code I had

logging.warning("look out)"

...
ch = logging.StreamHandler(sys.stdout)
root = logging.getLogger()
root.addHandler(ch)

root.info("hello")

I would get something like (ignoring the format options)

look out
hello
hello

and everything was written to stdout twice. I believe this is because the first call to logging.warning creates a new handler automatically, and then I explicitly added another handler. The problem went away when I removed the accidental first logging.warning call.

I was getting a strange situation where console logs were doubled but my file logs were not. After a ton of digging I figured it out.

Please be aware that third party packages can register loggers. This is something to watch out for (and in some cases can’t be prevented). In many cases third party code checks to see if there are any existing root logger handlers; and if there isn’t–they register a new console handler.

My solution to this was to register my console logger at the root level:

rootLogger = logging.getLogger()  # note no text passed in--that's how we grab the root logger
if not rootLogger.handlers:
        ch = logging.StreamHandler()
        ch.setLevel(logging.INFO)
        ch.setFormatter(logging.Formatter('%(process)s|%(levelname)s] %(message)s'))
        rootLogger.addHandler(ch)