CODEWITHSUNDEEP
pythonloggingpython-logging
iandresolares
iandresolares

Reputation: 43

Logging printing twice only in some parts of the code

I have been using a custom formatter for logging to the terminal in my code. Lately I have been changing stuff in the code an I can't find why now in some parts of the code the log is printed twice. This is the code for the custom formatter:

import logging

class MyFormatter(logging.Formatter):

    debug_format = "[%(levelname)s] (%(module)s::%(funcName)s::%(lineno)d) %(message)s"
    normal_format = "[%(levelname)s] %(message)s"

    blue = "\x1b[36;21m"
    grey = "\x1b[38;21m"
    yellow = "\x1b[33;21m"
    red = "\x1b[31;21m"
    bold_red = "\x1b[31;1m"
    reset = "\x1b[0m"

    def __init__(self):
        super().__init__(fmt="%(levelno)d: %(msg)s", datefmt=None, style="%")

    def format(self, record):

        # Save the original format configured by the user
        # when the logger formatter was instantiated
        format_orig = self._style._fmt

        # Replace the original format with one customized by logging level
        if record.levelno == logging.DEBUG:
            self._style._fmt = MyFormatter.debug_format
            format = MyFormatter.debug_format
        else:
            self._style._fmt = MyFormatter.normal_format
            format = MyFormatter.normal_format

        self.FORMATS = {
            logging.DEBUG: MyFormatter.grey + format + MyFormatter.reset,
            logging.INFO: MyFormatter.blue + format + MyFormatter.reset,
            logging.WARNING: MyFormatter.yellow + format + MyFormatter.reset,
            logging.ERROR: MyFormatter.red + format + MyFormatter.reset,
            logging.CRITICAL: MyFormatter.bold_red + format + MyFormatter.reset,
        }

        log_fmt = self.FORMATS.get(record.levelno)

        # Restore the original format configured by the user
        self._style._fmt = format_orig

        formatter = logging.Formatter(log_fmt)
        return formatter.format(record)

This is how I create my logger:

from src.logs import set_logger, logging

logger = set_logger(__name__, logging.DEBUG)

This is set_logger function code:

import logging
from .custom_formatter import MyFormatter

def set_logger(module_name: str, level=logging.DEBUG) -> logging.Logger:
    logger = logging.getLogger(module_name)
    logger.setLevel(level)

    stream_handler = logging.StreamHandler()
    formatter = MyFormatter()
    stream_handler.setFormatter(formatter)
    logger.addHandler(stream_handler)
    return logger

Now when I call this logger from main for example or at the top of a module which is imported, there is no problem, and it logs perfectly only once. However when calling the logger from inside a function in the same module it is printed twice. I have notice by debugging that what is doing is going to the end of the format method in MyFormatter class and then it returns again to this format method, I have no clue what is going on here. Do you have any ideas on what could be happening?

PD: Also if I also call a print when the logger prints twice I only get one print, so that code runs only once for sure.

Thanks for your time!

Andrés

Upvotes: 2

Views: 1695

Answers (1)

Martin Stone
Martin Stone

Reputation: 13007

In set_logger(), it calls addHandler() but the logger (or an ancestor logger) will already have a handler, which you're not removing, so you'll have multiple handlers.

Have a look at the docs for Logger.propagate: https://docs.python.org/3/library/logging.html#logging.Logger.propagate

Upvotes: 4

Related Questions