CODEWITHSUNDEEP
pythonlogging
Nikhil Singh
Nikhil Singh

Reputation: 665

Python logging module is printing lines multiple times

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?

Upvotes: 36

Views: 28663

Answers (5)

Sevki Baba
Sevki Baba

Reputation: 366

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

Upvotes: 0

JackOAllTrades
JackOAllTrades

Reputation: 21

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
>>>

Upvotes: 2

falsetru
falsetru

Reputation: 369064

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

Upvotes: 51

toom
toom

Reputation: 13316

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

Upvotes: 5

Sanju
Sanju

Reputation: 2194

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
# ....

Upvotes: 25

Related Questions