Python logging module is printing lines multiple times

Question

I have the following code:

import logging
class A(object):
    def __init__(self):
        self._l = self._get_logger()

    def _get_logger(self):
        loglevel = logging.INFO
        l = logging.getLogger(__name__)
        l.setLevel(logging.INFO)
        h = logging.StreamHandler()
        f = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
        h.setFormatter(f)
        l.addHandler(h)
        l.setLevel(loglevel)
        return l  

    def p(self, msg):
        self._l.info(msg)

for msg in ["hey", "there"]:
    a = A()
    a.p(msg)

The output that I get is:

2013-07-19 17:42:02,657 INFO hey
2013-07-19 17:42:02,657 INFO there
2013-07-19 17:42:02,657 INFO there

Why is "there" being printed twice? Similarly, if I add another object of class A inside the loop and print a message, it gets printed thrice.

The documentation says that logging.getLogger() will always return the same instance of the logger if the name of the logger matches. In this case, the name does match. Should it not return the same logger instance? If it is infact doing so, why is the message getting printed multiple times?

falsetru · Accepted Answer · 2018-10-12T22:48:20.563

44

logger is created once, but multiple handlers are created.

Create A once.

a = A()
for msg in ["hey", "there"]:
    a.p(msg)

Or change _get_logger as follow:

def _get_logger(self):
    loglevel = logging.INFO
    l = logging.getLogger(__name__)
    if not getattr(l, 'handler_set', None):
        l.setLevel(loglevel)
        h = logging.StreamHandler()
        f = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
        h.setFormatter(f)
        l.addHandler(h)
        l.setLevel(loglevel)
        l.handler_set = True
    return l

UPDATE

Since Python 3.2, you can use logging.Logger.hasHandlers to see if this logger has any handlers configured. (thanks @toom)

def _get_logger(self):
    loglevel = logging.INFO
    l = logging.getLogger(__name__)
    if not l.hasHandlers():
        ...
    return l

edited Oct 12 '18 at 22:48

answered Jul 19 '13 at 12:20

falsetru

357,413
63
732
636

My use case is different. I want to be able to spawn multiple objects of a class that implements its own logger. Is this the right way of doing things? Also, why are the log lines getting printed multiple times? – Nikhil Singh Jul 19 '13 at 12:25
2

@NikhilSingh: `getLogger` does return the same logger every time, but then each time you instantiate `A`, you're calling `addHandler` on that same logger. It will print a message for every handler you've added. – Wooble Jul 19 '13 at 12:27
You are constructing the logger handler once for each A instance. You are creating an A instance for "hey" and "there", so two handlers. Change the line to `["hey", "there", "buddy"]` and you'll get 3 copies of "buddy". Only create the A._l logger once per class, not once per instance. – PaulMcG Jul 19 '13 at 12:29
1

Since python 3.2: You should consider `l = logging.getLogger(__name__)` and then `l.hasHandlers()` method. Does exactly the job! https://docs.python.org/3/library/logging.html#logging.Logger.hasHandlers – toom Oct 11 '18 at 11:28
@toom, Thank you for the information. I updated the answer to include that information. Didn't noticed the method. +1 – falsetru Oct 12 '18 at 22:50
Just for my understanding: can it be that `len(l.handlers) == 0` and `l.hasHandlers() == True` if the parent logger has a handler? Because what I want is to avoid adding my handler twice, but I don't want not adding it because there is some other handler higher up in the logging hierarchy. – HerrIvan Sep 30 '21 at 16:29

score 22 · Answer 2 · answered May 20 '16 at 07:37

22

In my case , the root loggers handler were also being called , All I did was to set propagate attribute of logger instance to False.

import logging
logger = logging.getLogger("MyLogger")

# stop propagting to root logger
logger.propagate = False

# other log configuration stuff
# ....

answered May 20 '16 at 07:37

Sanju

1,974
1
18
33

With this, you avoid printing many times the same information in every run of the script when using the same kernel. – Lucho Aug 04 '21 at 09:08

score 5 · Answer 3 · answered Oct 11 '18 at 11:30

5

Since python 3.2 and newer:

Consider using hasHandlers() to check if a logger has handlers or not.

https://docs.python.org/3/library/logging.html#logging.Logger.hasHandlers

answered Oct 11 '18 at 11:30

toom

12,864
27
89
128

score 2 · Answer 4 · answered Apr 22 '19 at 07:27

Best to set up the logger at the module level outside all classes and functions to avoid having it repeatedly setting up the handler.

For use cases where that's unavoidable, check the number of handlers already attached to the named logger, or better still check presence of the handler in the list. In Python 2.7.6, Logger's class attribute handlers is a list of the handlers set up on the Logger class instance. Don't attach a handler that's already in the list. E.g.

>>> import logging
>>> import logging.handlers # lib of log record handlers
>>> dir(logging.handlers)   # all the handlers from the lib
['BaseRotatingHandler', 'BufferingHandler', 'DEFAULT_HTTP_LOGGING_PORT', 'DEFAULT_SOAP_LOGGING_PORT', 'DEFAULT_TCP_LOGGING_PORT', 'DEFAULT_UDP_LOGGING_PORT', 'DatagramHandler', 'HTTPHandler', 'MemoryHandler', 'NTEventLogHandler', 'RotatingFileHandler', 'SMTPHandler', 'ST_DEV', 'ST_INO', 'ST_MTIME', 'SYSLOG_TCP_PORT', 'SYSLOG_UDP_PORT', 'SocketHandler', 'SysLogHandler', 'TimedRotatingFileHandler', 'WatchedFileHandler', '_MIDNIGHT', '__builtins__', '__doc__', '__file__', '__name__', '__package__', '_unicode', 'cPickle', 'codecs', 'errno', 'logging', 'os', 're', 'socket', 'struct', 'time']
>>> l = logging.getLogger()   # root logger
>>> l.addHandler(logging.handlers.TimedRotatingFileHandler)
>>> l.addHandler(logging.handlers.WatchedFileHandler)
>>> l.handlers  # handlers set up on the logger instance
[<class 'logging.handlers.TimedRotatingFileHandler'>, <class 'logging.handlers.WatchedFileHandler'>]
>>> logging.handlers.TimedRotatingFileHandler in l.handlers # check - Yes
True
>>> logging.handlers.WatchedFileHandler in l.handlers # check - Yes
True
>>> logging.handlers.HTTPHandler in l.handlers # check - No
False
>>>

score 0 · Answer 5 · answered Aug 20 '23 at 20:22

The trick is setting the name of the handler and then checking if that exists. See the below python code for an example code that creates multiple files for multiple loggers. Also, you might need to run this code piece in a higher execution context and pass the logger to the subclasses.

def get_logger_(unique_name):
    logger = logging.getLogger(f'{unique_name}_logger')
    for lll in logger.handlers:
        if lll.name == f'{unique_name}_logger':
            return logger
    logger.setLevel(logging.INFO)
    file_handler = logging.FileHandler(f'{unique_name}.log')
    file_handler.setLevel(logging.INFO)
    file_handler.setFormatter(logging.Formatter('%(asctime)s %(message)s'))
    file_handler.name = f'{unique_name}_logger'
    logger.addHandler(file_handler)
    return logger

Python logging module is printing lines multiple times

5 Answers5

Linked

Related