log messages appearing twice with Python Logging

Question

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. I'm assuming I've missed something obvious.

Nogging

Are you sure configure_logging() is not called twice (e.g. from the constructor too)? Is only one instance of Boy() created? – Meanwhile

Using self.logger.handlers = [ch] instead would solve this problem, though it would be best just to ensure that you don't run this code twice by, for example, using if not self.logger at the start. – Elbow

Check this out, don't forget to name your handlers, https://mcmap.net/q/67525/-python-logging-retrieve-specific-handler – Sargeant

Answer 1

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)

Heaven

Yes, you were right - silly me. I called it in init, as well as explicitly elsewhere. Lol. Thanks =). – Nogging

In my case, they were appearing 6 times. I had suspected that because I've declared the same type of logger in 6 oop classes – Ulund

I'd like to share here my experience: for a Flask application which I developed, the log messages were appearing MORE THAN TWICE. I'd say that they were incrementing on the log file, due to the fact that, when the application and the modules were loaded, the logger variable used, was not the one instantiated from one of my classes, but the logger variable present on Python3 cache, and the handler was added every 60 sec by an AppScheduler which I configured. So, this if not logger.handlers is a pretty smart way to avoid this type of phenomenon. Thanks for the solution, comrade :)! – Epigraphic

I'm seeing this problem in my Flask app. This solution fixed the problem for log messages generated in the main flask app, but my app cals functions in a library module, and those messages from that library are still getting logged multiple times. I don't know how to fix this. – Passible

i had a different solution which fixed for me. i had a file config and had propagate set to 1 there for logger. i removed it and it fixed the issue. if possible , can someone please explain me why. since issue is fixed, i did not open a new thread – Adrenocorticotropic

Answer 2

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

Haplology

That's the best answer. It did not fit the purpose of the poster (logical error in coding) but most of the times, this should be the case. – Picul

Bravo. THIS is the actual cause of the duplicates (for the most general cases). – Ennead

Why cant this be default. I build all my loggers under "root." + directory structure, so I can easily control everything from the 'root' logger – Secundas

This is what helped me understand that this is the right answer (if it's not a code bug that is): jdhao.github.io/2020/06/20/python_duplicate_logging_messages – Blinkers

Answer 3

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

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

Cogency

This worked for me, but prefer using logger.handlers.clear() – Jola

Answer 4

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

Weingarten

This is the issue I have. Thank you – Ozellaozen

Great answer; adding logger.propagate = False was the solution to prevent double logging in a Flask application hosted by Waitress, when logging to Flask's app.logger instance. – Justiceship

Answer 5

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

self.logger.removeHandler(ch)

Passbook

I used logger.handlers.pop() in python 2.7, does the trick – Carnelian

Answer 6

This can also happen if you are trying to create a logging object from the parent file. For e.g. This is the main application file test.py

import logging

# create logger
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)

# create console handler and set level to debug
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# create formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# add formatter to ch
ch.setFormatter(formatter)

# add ch to logger
logger.addHandler(ch)

def my_code():
# 'application' code
    logger.debug('debug message')
    logger.info('info message')
    logger.warning('warn message')
    logger.error('error message')
    logger.critical('critical message')

And below is the parent file main.py

import test

test.my_code()

The output of this will print only once

2021-09-26 11:10:20,514 - simple_example - DEBUG - debug message
2021-09-26 11:10:20,514 - simple_example - INFO - info message
2021-09-26 11:10:20,514 - simple_example - WARNING - warn message
2021-09-26 11:10:20,514 - simple_example - ERROR - error message
2021-09-26 11:10:20,514 - simple_example - CRITICAL - critical message

But if we had a parent logging object, then it will be printed twice. For e.g. if this is the parent file

import test
import logging
logging.basicConfig(level=logging.DEBUG,format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')


test.my_code()

The the output will be

2021-09-26 11:16:28,679 - simple_example - DEBUG - debug message
2021-09-26 11:16:28,679 - simple_example - DEBUG - debug message
2021-09-26 11:16:28,679 - simple_example - INFO - info message
2021-09-26 11:16:28,679 - simple_example - INFO - info message
2021-09-26 11:16:28,679 - simple_example - WARNING - warn message
2021-09-26 11:16:28,679 - simple_example - WARNING - warn message
2021-09-26 11:16:28,679 - simple_example - ERROR - error message
2021-09-26 11:16:28,679 - simple_example - ERROR - error message
2021-09-26 11:16:28,679 - simple_example - CRITICAL - critical message
2021-09-26 11:16:28,679 - simple_example - CRITICAL - critical message

Arbutus

Answer 7

Adding to others' useful responses...

In case you are NOT accidentally configuring more than one handler on your logger:

When your logger has ancestors(root logger is always one) and they have their own handlers, they will also output when your logger outputs (by default), which will create duplicates. You have two options:

• Don't propagate your log event to your ancestors by setting:

my_logger.propagate = False

• If you only have one ancestor(root logger), you could directly configure their handler instead. For example:

# directly change the formatting of root's handler
root_logger = logging.getLogger()
roots_handler = root_logger.handlers[0]
roots_handler.setFormatter(logging.Formatter(': %(message)s')) # change format

my_logger = logging.getLogger('my_logger') # my_logger will use new formatting

Gorgeous

Answer 8

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.

Taro

I think this is what's going on for me. How do you prevent the automatic creation of console loggers? – Disused

@Disused it's about making sure you're initialized with the logger you want, before the first logging call. Testing frameworks can obscure this, but there should be a way to do it. Also, if you're multiprocessing you have to do the same with each process. – Taro

Answer 9

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.

Cryptogam

Answer 10

I was struggling with the same issue in the context of multiple processes. (For the code see the docs which I was following almost verbatim.) Namely, all log messages originating from any of the child processes got duplicated.

My mistake was to call worker_configurer(),

def worker_configurer(logging_queue):
    queue_handler = logging.handlers.QueueHandler(logging_queue)
    root = logging.getLogger()
    root.addHandler(queue_handler)
    root.setLevel(level)

both in the child processes and also in the main process (since I wanted the main process to log stuff, too). The reason this led to trouble (on my Linux machine) is that on Linux the child processes got started through forking and therefore inherited the existing log handlers from the main process. That is, on Linux the QueueHandler got registered twice.

Now, preventing the QueueHandler from getting registered twice in the worker_configurer() function is not as trivial as it seems:

• Logger objects like the root logger root have a handlers property but it is undocumented.

• In my experience, testing whether any([handler is queue_handler for handler in root.handlers]) (identity) or any([handler == queue_handler for handler in root.handlers]) (equality) fails after forking, even if root.handlers seemingly contains the same QueueHandler. (Obviously, the previous two expressions can be abbreviated by queue_handler in root.handlers, since the in operator checks for both identity and equality in the case of lists.)

• The root logger gets modified by packages like pytest, so root.handlers and root.hasHandlers() are not very reliable to begin with. (They are global state, after all.)

The clean solution, therefore, is to replace forking with spawning to prevent these kinds of multiprocessing bugs right from the start (provided you can live with the additional memory footprint, of course). Or to use an alternative to the logging package that doesn't rely on global state and instead requires you to do proper dependency injection but I'm digressing… :)

With that being said, I ended up going for a rather trivial check:

def worker_configurer(logging_queue):
    queue_handler = logging.handlers.QueueHandler(logging_queue)
    root = logging.getLogger()

    for handler in root.handlers:
        if isinstance(handler, logging.handlers.QueueHandler):
            return

    root.addHandler(queue_handler)
    root.setLevel(level)

Obviously, this will have nasty side effects the second I decide to register a second queue handler somewhere else.

Cynosure

Answer 11

From the docs:

"Loggers have the following attributes and methods. 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".

Make sure you don't initialise your loggers with the same name I advise you to initialise the logger with __name__ as name param i.e:

import logging
logger = logging.getLogger(__name__)

NOTE: even if you init a loggers from other modules with same name, you will still get the same logger, therefore calling i.e logger.info('somthing') will log as many times as you initiated the logger class.

Carlton

Answer 12

I tried many things and finally came up with my custom logger. You just need to copy and paste it in your code and it will do the work you required.

Why to use?

1. No repeated logs.
2. Separate customisation for info logs - [ Not contains path and unnecessary details ]
3. Different colours to different log levels.
4. You will get all the different levels of logs - [ info, warning, error, critical, debug ,... ].

import logging


class CustomFormatter(logging.Formatter):
    def __init__(self) -> None:
        super().__init__()

    def format(self, record):
        if record.levelno == logging.INFO:
            self._style._fmt = "%(levelname)-5s  %(asctime)-3s %(message)s"
        else:
            color = {
                logging.WARNING: 33,
                logging.ERROR: 31,
                logging.FATAL: 31,
                # logging.DEBUG: 36
            }.get(record.levelno, 0)
            self._style._fmt = f'\033[{color}m%(levelname)-5s %(asctime)s file/"%(pathname)10s", line %(lineno)d in "%(funcName)s" -> "%(message)s" \033[0m'
        return super().format(record)


logger = logging.getLogger("my-logger")
if not logger.handlers:
    handler = logging.StreamHandler()
    handler.setFormatter(CustomFormatter())
    logger.addHandler(handler)
    logger.setLevel(logging.DEBUG)
    logger.propagate = False
    # to disable any level of logs; eg - disabled debug level logs.
    logging.disable(logging.DEBUG)

What you will get [ *it will be with different colours in you colsole/log file ]

logger.info("This is info log")

INFO 2023-03-24 20:11:51,230 This is info log

logger.warning("This is warning log")

WARNING 2023-03-24 20:11:51,230 file/"/home/xyz/abc", line 25 in "my_function" -> "This is warning log"

logger.error("This is error log")

ERROR 2023-03-24 20:11:51,230 file/"/home/xyz/abc", line 26 in "my_function" -> "This is error log"

logger.critical("This is critical log")

CRITICAL 2023-03-24 20:11:51,231 file/"/home/xyz/abc", line 27 in "my_function" -> "This is critical log"

logger.debug("This is debug log")

DEBUG 2023-03-24 20:11:51,231 file/"/home/xyz/abc", line 28 in "my_function" -> "This is debug log"

Note - I have disabled the debug level log in the above code, to use comment/remove the lines.

Duiker

Answer 13

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)

Disused

Answer 14

If you are using any config for logging, For instance log.conf

In .conf file you can do it by adding this line in the [logger_myLogger] section: propagate=0

[logger_myLogger]
level=DEBUG
handlers=validate,consoleHandler
qualname=VALIDATOR
propagate=0

Fruity

Answer 15

If you use the standard construction logger = logging.getLogger('mymodule') and then accidentally mistype loggger as logging i.e.

logger = logging.getLogger('mymodule')

# configure your handlers

logger.info("my info message")  # won't make duplicate 
logging.info("my info message")  # will make duplicate logs

then this will cause duplicate messages to come up because the call to logging creates a new logger.

Siliceous

Answer 16

I had the same issue. In my case, it was not due to handlers or duplicate initial configuration but a stupid typo. In main.py I was using a logger object but in my_tool.py I was directly calling to the logging module by mistake, hence after invoking functions from my_tool module everything was messed up and the messages appeared duplicated.

This was the code:

main.py

import logging
import my_tool

logger_name = "cli"
logger = logging.getLogger(logger_name)

logger.info("potato")
logger.debug("potato)
my_tool.function()
logger.info("tomato")

my_tool.py

import logging
logger_name = "cli"
logger = logging.getLogger(logger_name)
# some code
logging.info("carrot")

and the result

terminal

>> potato
>> potato
>> carrot
>> tomato
>> tomato

Bumbailiff