Duplicate log output when using Python logging module

Question

I am using python logger. The following is my code:

import os
import time
import datetime
import logging
class Logger :
   def myLogger(self):
      logger = logging.getLogger('ProvisioningPython')
      logger.setLevel(logging.DEBUG)
      now = datetime.datetime.now()
      handler=logging.FileHandler('/root/credentials/Logs/ProvisioningPython'+ now.strftime("%Y-%m-%d") +'.log')
      formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
      handler.setFormatter(formatter)
      logger.addHandler(handler)
      return logger

The problem I have is that I get multiple entries in the log file for each logger.info call. How can I solve this?

Onym

Works for me. Python 3.2 and Windows XP. – Considerate

Are you sure you don't create multiple logger instances? – Brownlee

Yes. in different file I am taking new instance as we did in Java projects. Please specify me whether that is creating problem or not. – Onym

Answer 1

Function logging.getLogger() returns the same instance for a given name.

The problem is that every time you call myLogger(), it's adding another handler to the instance, which causes the duplicate logs.

Perhaps something like this?

import os
import time
import datetime
import logging

loggers = {}

def myLogger(name):
    global loggers
    
    if loggers.get(name):
        return loggers.get(name)
    else:
        logger = logging.getLogger(name)
        logger.setLevel(logging.DEBUG)
        now = datetime.datetime.now()
        handler = logging.FileHandler(
            '/root/credentials/Logs/ProvisioningPython' 
            + now.strftime("%Y-%m-%d") 
            + '.log')
        formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
        handler.setFormatter(formatter)
        logger.addHandler(handler)
        loggers[name] = logger
                       
        return logger

Exodus

isn't the global loggers dictionary redundant with logging.getLogger? since you really just want to avoid adding extra handlers, it seems like you'd prefer the answers below that check for handlers directly – Meredeth

Answer 2

Since Python 3.2 you can just check if handlers are already present and if so, clear them before adding new handlers. This is pretty convenient when debugging and the code includes your logger initialization

if (logger.hasHandlers()):
    logger.handlers.clear()

logger.addHandler(handler)

Bodgie

Note that hasHandlers() will return true in pytest where a handler has been added to the root logger, even if your local/custom handlers have not yet been added. The len(logger.handlers) (as per Guillaume's answer) will return 0 in this case, so may be a better option. – Cephalad

This is real solution what I was looking for. – Charliecharline

This works when the existing handler belongs directly to my logger, but not if the handler is from a parent of my logger. In that case, only logger.propagate = False removes the duplicates as mentioned below in @Mr. B's answer. Is there a way to clear parent handlers? – Sitology

Answer 3

I already used the logger as a Singleton and checked if not len(logger.handlers), but still got duplicates: It was the formatted output, followed by the unformatted.

Solution in my case: logger.propagate = False

Credits to this answer and the docs.

Spore

I had figured out that the doubled logging was from RootLogger and my StreamHandler, but couldn't resolve the issue (while keeping my formatter on the StreamHandler) until doing this. – Preindicate

I had a similar issue where logger duplicated outputs after a call to logging.info(). By only emitting messages through my logger singleton and not the logging module's info() method, I was able to avoid duplicate output – Sitology

Have the same problem, after my formatted logs go non-formatted (it root logs). Your approach helped me resolve that problem. Thanks a lot. – Nameless

@Nameless Happy to help! :) – Spore

@Mr.B. Note that logger.propagate can be added to the config (or yaml etc.). But I read elsewhere that root always has propagate = True, so I am confused. I am wondering if it environment-specific. Can I clarify or do you already know what it going on? Thanks! – Merow

@Merow thanks for the hint! Unfortunately I've no deeper knowledge and was just happy that it solved the issue back then. :) – Spore

Finally a solution that works! – Cage

Finally, Thanks!! – Kobe

Answer 4

import datetime
import logging
class Logger :
    def myLogger(self):
       logger=logging.getLogger('ProvisioningPython')
       if not len(logger.handlers):
          logger.setLevel(logging.DEBUG)
          now = datetime.datetime.now()
          handler=logging.FileHandler('/root/credentials/Logs/ProvisioningPython'+ now.strftime("%Y-%m-%d") +'.log')
          formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
          handler.setFormatter(formatter)
          logger.addHandler(handler)
        return logger

made the trick for me

using python 2.7

Schlessel

This works even when the module is reloaded (which is not the case of the other answers) – Otes

Thanks for the tip, BTW to check if a list is empty or not you don't need to use the "len" operator you can directly use if my_list: .. – Leitman

Answer 5

This is an addition to @rm957377's answer but with an explanation of why this is happening. When you run a lambda function in AWS, they call your function from within a wrapping instance that stays alive for multiple calls. Meaning, if you call addHandler() within the code of your function, it will continue to add duplicate handlers to the logging singleton every time the function runs. The logging singleton persists through multiple calls of you lambda function.

To solve this you can clear your handlers before you set them via:

logging.getLogger().handlers.clear()
logging.getLogger().addHandler(...)

Marilyn

Somehow in my case the logger handlers get added at the event on .info() call which I do not understand. – Macon

handlers.clear() gives me an error in python 2, it says clear is not a method of a list. Maybe this is a method in python 3? I did this instead: logging.getLogger().handlers = list(). Seems to work fine. – Eurythermal

Answer 6

You are calling Logger.myLogger() more than once. Store the logger instance it returns somewhere and reuse that.

Also be advised that if you log before any handler is added, a default StreamHandler(sys.stderr) will be created.

Aliber

Actually I am trying to access the logger instance as we use in java.But I do not know whether it's need to create a instance only once for a whole project or not. – Onym

@user865483: Just once. All the standard library loggers are singletons. – Aliber

Answer 7

The problem is the number handlers, if you have multiple handlers you have multiples logs so you just have to check before add:

if not logger.handlers:
    logger.addHandler(handler)

Memoir

Answer 8

The implementation of logger is already a singleton.

Multiple calls to logging.getLogger('someLogger') return a reference to the same logger object. This is true not only within the same module, but also across modules as long as it is in the same Python interpreter process. It is true for references to the same object; additionally, application code can define and configure a parent logger in one module and create (but not configure) a child logger in a separate module, and all logger calls to the child will pass up to the parent. Here is a main module

Source- Using logging in multiple modules

So the way you should utilize this is -

Let's suppose we have created and configured a logger called 'main_logger' in the main module (which simply configures the logger, doesn't return anything).

# get the logger instance
logger = logging.getLogger("main_logger")
# configuration follows
...

Now in a sub-module, if we create a child logger following the naming hierarchy 'main_logger.sub_module_logger', we don't need to configure it in the sub-module. Just creation of the logger following the naming hierarchy is sufficient.

# get the logger instance
logger = logging.getLogger("main_logger.sub_module_logger")
# no configuration needed
# it inherits the configuration from the parent logger
...

And it won't add duplicate handler as well.

See this question for a little more verbose answer.

Ehrenburg

redefining handlers after getLogger seems to work for me: logger = logging.getLogger('my_logger') ; logger.handlers = [logger.handlers[0], ] – Unfriendly

This is a GREAT answer better than othersIMO – Grivation

exactly, while other answers do aim at resolving the question ‘as asked’, this one is actually challenging the question itself and proposes the way it should be done. – Wight

Answer 9

Your logger should work as singleton. You shouldn't create it more than once. Here is example how it might look:

import os
import time
import datetime
import logging
class Logger :
    logger = None
    def myLogger(self):
        if None == self.logger:
            self.logger=logging.getLogger('ProvisioningPython')
            self.logger.setLevel(logging.DEBUG)
            now = datetime.datetime.now()
            handler=logging.FileHandler('ProvisioningPython'+ now.strftime("%Y-%m-%d") +'.log')
            formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
            handler.setFormatter(formatter)
            self.logger.addHandler(handler)
        return self.logger

s = Logger()
m = s.myLogger()
m2 = s.myLogger()
m.info("Info1")
m2.info("info2")

Considerate

then again if I am going to take the different instance in different file. Suppose in file 1 s = Logger() m = s.myLogger() and in file 2 s = Logger() It will work or not m2 = s.myLogger() – Onym

Still I am getting copy of same log several times. I have a doubt here whether inside thread Log prints more than one or not.Please help me in this. – Onym

@user865438, we do not need to worry about making the implementation a singleton(It already is). For logging in sub-modules, follow the official Logging Cookbook link. Basically you need to follow the naming hierarchy while naming the loggers and it takes care of the rest. – Ehrenburg

Answer 10

When we use getLogger() without any argument, it returns RootLogger.

So if you invoke getLogger() at multiple places and add log handler, it will add those log handlers to the RootLogger (If you don't add log handler explicitly, it will add StreamHandler automatically). Thus, when you will try to log messages, it will log messages using all the handlers added to RootLogger. This is the cause of duplicate logs.

You can avoid this by just providing a different logger name when you invoke getLogger(). Something like

logger1 = logging.getLogger("loggera")

logger2 = logging.getLogger("loggerb")

This is something that worked for me.

Naivete

Answer 11

One simple workaround is like

logger.handlers[:] = [handler]

This way you avoid appending new handler to the underlying list "handlers".

Osman

Answer 12

Double (or triple or ..- based on number of reloads) logger output may also happen when you reload your module via importlib.reload (for the same reason as explained in accepted answer). I am adding this answer just for a future reference as it took me a while to figure out why my output is dupli(triple)cated.

Nitrification

Answer 13

Bottom line for most cases when this happens, one only needs to call logger.getLogger() only once per module. If you have multiple classes like I did, I could call it like so:

LOGGER = logger.getLogger(__name__)

class MyClass1:
    log = LOGGER
    def __init__(self):
        self.log.debug('class 1 initialized')

class MyClass2:
    log = LOGGER
    def __init__(self):
        self.log.debug('class 2 initialized')

Both then will have their own full package name and method where logged.

Iredale

Answer 14

Let me add what caused my pain.

In a nutshell, in a utility module, I'm importing logging only for type-hinting. And I pass in the logger from the invoker module, to make sure we are using the logger object, as in the example code.

But my logs had duplicated lines, one formatted as it was set in my logger object, the duplicate on the other hand was unformatted with exactly the same content.

import logging

import paramiko

# make paramiko module logging less chatty 
logging.getLogger("paramiko").setLevel(logging.WARNING)


def validate_s3_prefix_string(s3_bucket_prefix_: str, logger_: logging.Logger, log_level_: str = 'warning') -> str:
    if not s3_bucket_prefix_.endswith('/'):
        message = f"Invalid S3 bucket prefix: {s3_bucket_prefix_}. It should end with '/'"
        if log_level_ == 'warning':
            logger_.warning(message)
        elif log_level_ == 'error':
            logger_.error(message)
            raise ValueError(message)
    else:
        logging.info(f"The S3 bucket prefix seems to be in the correct format: {s3_bucket_prefix_}")
    return s3_bucket_prefix_

# ... the rest of the file

It took me a while until I spot the issue. If you have not found it yourself then here it is:

    logging.info(f"The S3 bucket prefix seems to be in the correct format: {s3_bucket_prefix_}")

I accidentally used logging to write a message instead of the passed-in logging object.

We can use the logging base object to log, but when used it will automatically create and add a stream handler, but it is not configured.

Simply changing to the logging object in the parameters solved my problem for good.
So for the sake of completeness, the code should have looked like this:

    logger_.info(f"The S3 bucket prefix seems to be in the correct format: {s3_bucket_prefix_}")

I hope it helps someone else to tackle this tiny headache.

Rivarivage

Answer 15

You are able to get list of all handlers for the particular logger, so you can do something like this

logger = logging.getLogger(logger_name)
handler_installed = False
for handler in logger:
    # Here your condition to check for handler presence
    if isinstance(handler, logging.FileHandler) and handler.baseFilename == log_filename:
        handler_installed = True
        break

if not handler_installed:
    logger.addHandler(your_handler)

In the example above we check if the handler for a file specified is already hooked to the logger, but having access to the list of all handlers gives you an ability to decide on which criteria you should add another handler or not.

Parsimony

Answer 16

Had this problem today. Since my functions were @staticmethod the above suggestions were resolved with random().

Looking something like:

import random

logger = logging.getLogger('ProvisioningPython.{}'.format(random.random()))

Doubleganger

Answer 17

I have 3 handlers in one logger

StreamHandler setLevel(args.logging_level)
logging.FileHandler(logging.ERROR)
RotatingFileHandler(args.logging_level)
logger.setLevel(args.logging_level)

I had my code using

logger = logging.getLogger('same_name_everywhere')

resulting duplicated lines and duplicated handlers like this, 2 Stream Handlers, 3 Rotating FileHanders While 1 Stream Handler + 2 Rotating FileHanders(1 for errlog, 1 for generic log) This is done by

logger.warn(logger.handlers)
cli_normalize_string: WARNING  [<StreamHandler <stderr> (DEBUG)>, <RotatingFileHandler /tmp/cli.normalize_string.py.2020-11-02.user.errlog (ERROR)>, <StreamHandler <stderr> (DEBUG)>, <RotatingFileHandler /tmp/cli.normalize_string.py.2020-11-02.user.log (DEBUG)>, <RotatingFileHandler /tmp/cli.normalize_string.py.2020-11-02.user.errlog (ERROR)>]

After I changed to

# The name is now become change.cli_normalize_string or change.normalize_string
logger = logger.getLogger(__name__)

in every modules, issue resolved, no duplicated lines, 1 StreamHeader, 1 FileHandler for err logging, 1 RotatingFileHandler for generic logging

2020-11-02 21:26:05,856 cli_normalize_string INFO     [<StreamHandler <stderr> (DEBUG)>, <FileHandler /tmp/cli.normalize_string.py.2020-11-02.user.errlog (ERROR)>, <RotatingFileHandler /tmp/cli.normalize_string.py.2020-11-02.user.log (DEBUG)>]

The details is in this document https://docs.python.org/3/library/logging.html

Note that Loggers should NEVER be instantiated directly, but always through the module-level function logging.getLogger(name). Multiple calls to getLogger() with the same name will always return a reference to the same Logger object."

The name is potentially a period-separated hierarchical value, like foo.bar.baz (though it could also be just plain foo, for example). Loggers that are further down in the hierarchical list are children of loggers higher up in the list. For example, given a logger with a name of foo,

loggers with names of

foo.bar
foo.bar.baz

foo.bam 

are all descendants of foo. The logger name hierarchy is analogous to the Python package hierarchy, and identical to it if you organise

your loggers on a per-module basis using the recommended construction

logging.getLogger(__name__). 

That’s because in a module,

__name__ 

is the module’s name in the Python package namespace.

Homegrown

Answer 18

None of these worked for me as I discovered a semi-unique way to do this, but it is a variation on the themes here.

When creating my loggers with level, format, etc, I was adding BOTH sys.stdout AND sys.stderr and setting the log level to the same value for both.

Removing stderr solved my issue.

As I understand it, stdout contains all messages (above the minimum log level) and stderr should be log_level = 'ERROR' by default.

Broadloom

Answer 19

from logging.handlers import RotatingFileHandler
import logging
import datetime

# stores all the existing loggers
loggers = {}

def get_logger(name):

    # if a logger exists, return that logger, else create a new one
    global loggers
    if name in loggers.keys():
        return loggers[name]
    else:
        logger = logging.getLogger(name)
        logger.setLevel(logging.DEBUG)
        now = datetime.datetime.now()
        handler = logging.FileHandler(
            'path_of_your_log_file' 
            + now.strftime("%Y-%m-%d") 
            + '.log')
        formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
        handler.setFormatter(formatter)
        logger.addHandler(handler)
        loggers.update(dict(name=logger))
        return logger

Daric

Please add explanation to make this answer more valuable for long term use. – Propellant

This answer is very similar to the accepted answer (it even has the same bug dict(name=logger) fixed in Revision 3 of that answer), and has no explanation. – Chinchilla