Why does python's logging module duplicate messages in FastAPI?

Question

I want to add logging to my FastAPI application. I use the standard logging module in python for this. Logging is needed to collect application data while it is running. Just logging HTTP requests is not enough.

Simple FastAPI app for example:

import uvicorn
from fastapi import FastAPI

import logging
from logging.handlers import RotatingFileHandler, SysLogHandler
from logging import StreamHandler
import logging.config


class LogClass:
    def __init__(self,
                 log_format: str = f"%(asctime)s - [%(levelname)s] - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",
                 log_name: str = None,
                 maxFileSize: int = 1000000,
                 backupCount: int = 3,
                 syslog_host: str = None,
                 syslog_port: int = 514):

        self.log_backupCount = backupCount
        self.log_maxFileSize = maxFileSize
        self.log_format = log_format
        self.syslog_host = syslog_host
        self.syslog_port = syslog_port
        self.log_name = log_name

        self.logger = self.get_logger()

    def get_file_handler(self):
        file_handler = RotatingFileHandler(self.log_name, maxBytes=self.log_maxFileSize,
                                           backupCount=self.log_backupCount)
        file_handler.setLevel(logging.INFO)
        file_handler.setFormatter(logging.Formatter(self.log_format))
        return file_handler

    def get_stream_handler(self):
        stream_handler = StreamHandler()
        stream_handler.setLevel(logging.INFO)
        stream_handler.setFormatter(logging.Formatter(self.log_format))
        return stream_handler

    def get_syslog_handler(self):
        syslog_handler = SysLogHandler(address=(self.syslog_host, self.syslog_port))
        syslog_handler.setLevel(logging.INFO)
        syslog_handler.setFormatter(logging.Formatter(self.log_format))
        return syslog_handler

    def get_logger(self, stream: bool = True) -> logging.Logger:
        logger = logging.getLogger()
        logger.setLevel(logging.INFO)

        if self.log_name is not None:
            logger.addHandler(self.get_file_handler())
        if self.syslog_host is not None and self.syslog_port is not None:
            logger.addHandler(self.get_syslog_handler())
        if stream:
            logger.addHandler(self.get_stream_handler())

        return logger


app = FastAPI()


@app.get("/start")
async def start_func():
    log = LogClass()
    logger = log.logger
    logger.info("Message to log")

    return {"result": "OK"}


if __name__ == "__main__":
    uvicorn.run("test2_app:app", host="127.0.0.1", port=8000, reload=True)

PYTHONUNBUFFERED var set to 1.

But when I make simple curl requests, I see duplicate messages in the log. Something like this, when I send only three requests:

INFO:     127.0.0.1:52144 - "GET /start HTTP/1.1" 200 OK
2023-06-08 10:29:40,947 - [INFO] - (test2_app.py).start_func(70) - Message to log
2023-06-08 10:29:49,083 - [INFO] - (test2_app.py).start_func(70) - Message to log
2023-06-08 10:29:49,083 - [INFO] - (test2_app.py).start_func(70) - Message to log
INFO:     127.0.0.1:53004 - "GET /start HTTP/1.1" 200 OK
INFO:     127.0.0.1:53012 - "GET /start HTTP/1.1" 200 OK
2023-06-08 10:29:51,986 - [INFO] - (test2_app.py).start_func(70) - Message to log
2023-06-08 10:29:51,986 - [INFO] - (test2_app.py).start_func(70) - Message to log
2023-06-08 10:29:51,986 - [INFO] - (test2_app.py).start_func(70) - Message to log

I don't understand where the messages are duplicated. Can anyone help me get the correct log?

Does [this](https://stackoverflow.com/a/76322910/17865804) help? — Chris, Jun 10 '23 at 06:58
Thank you! This is a very interesting solution. I solved my problem simply by changing the logging module to loguru, there are no such problems with it. — izhatomic, Jun 10 '23 at 13:47
You might also find [this answer](https://stackoverflow.com/a/70899261/17865804) helpful — Chris, Jun 10 '23 at 14:56

score 0 · Answer 1 · answered Jun 08 '23 at 13:47

0

Messages are duplicated because you create a new instance of LogClass each time the route is called. The constructor calls get_logger which adds a new stream handler to the same logger object as per the Python doc:

Multiple calls to getLogger() with the same name will always return a reference to the same Logger object.

In your case, the logger name defaults to root since you didn't provide one in logging.getLogger().

Solution: you may want to have only one instance of your LogClass.

app = FastAPI()

log = LogClass()
logger = log.logger

@app.get("/start")
async def start_func():
    logger.info("Message to log")
    return {"result": "OK"}

answered Jun 08 '23 at 13:47

insideshell

1

I have tried this option. In this case, the messages in this log are also duplicated. – izhatomic Jun 08 '23 at 14:07
That's surprising, since I tried the solution before posting and messages are not duplicated this way. Can you double-check? Edit the original message with the new code and logs? – insideshell Jun 08 '23 at 14:18
I checked this before posting the answer. Yes, it is duplicated. screenshot: https://i.ibb.co/qkjw9w6/log.png – izhatomic Jun 08 '23 at 14:47
I cannot reproduced the issue on a fresh venv. Anyway, the issue you described in the first place was related to the consecutive instantiation of `LogClass`. – insideshell Jun 08 '23 at 16:03

Why does python's logging module duplicate messages in FastAPI?

1 Answers1