From 20919277d23876662984cfd66c728e97eae309c9 Mon Sep 17 00:00:00 2001 From: Jet Li Date: Fri, 31 Jan 2025 08:47:58 +0000 Subject: [PATCH] Fix the duplicated logging issue --- apps/content/common/log/application_logger.py | 6 +- apps/content/common/log/base_logger.py | 75 ++++++++-------- .../common/log/business_metric_logger.py | 9 +- apps/content/common/log/user_logger.py | 6 +- .../content/scheduler/cleanup_document_job.py | 4 - apps/content/webapi/bootstrap/application.py | 5 +- apps/content/webapi/providers/logger.py | 87 ++++++++----------- 7 files changed, 90 insertions(+), 102 deletions(-) diff --git a/apps/content/common/log/application_logger.py b/apps/content/common/log/application_logger.py index c1222bb..51d2cba 100644 --- a/apps/content/common/log/application_logger.py +++ b/apps/content/common/log/application_logger.py @@ -5,10 +5,10 @@ import json class ApplicationLogger(LoggerBase): def __init__(self, application_activities: dict[str, any] = {}) -> None: - extra_fileds = {} + extra_fields = {} if application_activities: - extra_fileds.update(application_activities) + extra_fields.update(application_activities) super().__init__( logger_name=app_settings.APPLICATION_ACTIVITY_LOG, - extra_fileds=extra_fileds, + extra_fields=extra_fields, ) diff --git a/apps/content/common/log/base_logger.py b/apps/content/common/log/base_logger.py index 4478fac..49e773d 100644 --- a/apps/content/common/log/base_logger.py +++ b/apps/content/common/log/base_logger.py @@ -1,49 +1,54 @@ from loguru import logger as guru_logger from common.config.log_settings import log_settings -from typing import List +from typing import Dict, Any import socket -import json -import logging import threading class LoggerBase: - binded_loggers = {} + binded_loggers = {} # Stores logger instances + loguru_sinks_added = set() # Tracks added log sinks logger_lock = threading.Lock() - def __init__(self, logger_name: str, extra_fileds: dict[str, any]) -> None: + def __init__(self, logger_name: str, extra_fields: Dict[str, Any] = None) -> None: self.__logger_name = logger_name - self.extra_fileds = extra_fileds + self.extra_fields = extra_fields or {} + with LoggerBase.logger_lock: + # ✅ **If already created, reuse it** to prevent duplicates if self.__logger_name in LoggerBase.binded_loggers: self.logger = LoggerBase.binded_loggers[self.__logger_name] return - log_filename = log_settings.LOG_BASE_PATH + "/" + self.__logger_name + ".log" - log_retention = log_settings.LOG_RETENTION - log_rotation = log_settings.LOG_ROTATION - log_level = "INFO" - log_message_format = "{message}" + log_filename = f"{log_settings.LOG_BASE_PATH}/{self.__logger_name}.log" - guru_logger.add( - sink=log_filename, - level=log_level, - retention=log_retention, - rotation=log_rotation, - format=log_message_format, - serialize=True, - filter=lambda record: "extra" in record - and "topic" in record["extra"] - and record["extra"]["topic"] == self.__logger_name, - ) - host_name = socket.gethostname() - host_ip = socket.gethostbyname(host_name) - self.logger = guru_logger.bind( - topic=self.__logger_name, - host_ip=host_ip, - host_name=host_name, - ) - with LoggerBase.logger_lock: + # ✅ **Ensure Loguru sink is added only once** + if log_filename not in LoggerBase.loguru_sinks_added: + guru_logger.add( + sink=log_filename, + level="INFO", + retention=log_settings.LOG_RETENTION, + rotation=log_settings.LOG_ROTATION, + format="{message}", + serialize=True, + filter=lambda record: "extra" in record + and "topic" in record["extra"] + and record["extra"]["topic"] == self.__logger_name, + ) + LoggerBase.loguru_sinks_added.add(log_filename) # ✅ Mark as added + + host_name = socket.gethostname() + host_ip = socket.gethostbyname(host_name) + + # ✅ Bind the logger with topic and extra fields + self.logger = guru_logger.bind( + topic=self.__logger_name, + host_ip=host_ip, + host_name=host_name, + **self.extra_fields, # Include additional metadata + ) + + # ✅ Store reference to prevent duplicate instances LoggerBase.binded_loggers[self.__logger_name] = self.logger async def log_event( @@ -52,7 +57,7 @@ class LoggerBase: receiver_id: str, subject: str, event: str, - properties: dict[str, any], + properties: Dict[str, Any], text: str = "", ) -> None: local_logger = self.logger.bind( @@ -71,7 +76,7 @@ class LoggerBase: subject: str, exception: Exception, text: str = "", - properties: dict[str, any] = None, + properties: Dict[str, Any] = None, ) -> None: local_logger = self.logger.bind( sender_id=sender_id, @@ -89,7 +94,7 @@ class LoggerBase: receiver_id: str, subject: str, text: str = "", - properties: dict[str, any] = None, + properties: Dict[str, Any] = None, ) -> None: local_logger = self.logger.bind( sender_id=sender_id, @@ -106,7 +111,7 @@ class LoggerBase: receiver_id: str, subject: str, text: str = "", - properties: dict[str, any] = None, + properties: Dict[str, Any] = None, ) -> None: local_logger = self.logger.bind( sender_id=sender_id, @@ -123,7 +128,7 @@ class LoggerBase: receiver_id: str, subject: str, text: str = "", - properties: dict[str, any] = None, + properties: Dict[str, Any] = None, ) -> None: local_logger = self.logger.bind( sender_id=sender_id, diff --git a/apps/content/common/log/business_metric_logger.py b/apps/content/common/log/business_metric_logger.py index 95383ab..734e49e 100644 --- a/apps/content/common/log/business_metric_logger.py +++ b/apps/content/common/log/business_metric_logger.py @@ -5,15 +5,14 @@ import json class BusinessMetricLogger(LoggerBase): def __init__(self, business_metrics: dict[str, any] = {}) -> None: - extra_fileds = {} + extra_fields = {} if business_metrics: - extra_fileds.update(business_metrics) + extra_fields.update(business_metrics) super().__init__( logger_name=app_settings.BUSINESS_METRIC_LOG, - extra_fileds=extra_fileds, + extra_fields=extra_fields, ) - async def log_metrics(self, business_metrics: dict[str, any] = {}) -> None: return await super().log_event( sender_id="business_metric_manager", @@ -21,5 +20,5 @@ class BusinessMetricLogger(LoggerBase): subject="metrics", event="logging", properties=business_metrics, - text="business metric logged" + text="business metric logged", ) diff --git a/apps/content/common/log/user_logger.py b/apps/content/common/log/user_logger.py index d931975..c866c87 100644 --- a/apps/content/common/log/user_logger.py +++ b/apps/content/common/log/user_logger.py @@ -6,9 +6,9 @@ import json class UserLogger(LoggerBase): def __init__(self, user_activities: dict[str, any] = {}) -> None: - extra_fileds = {} + extra_fields = {} if user_activities: - extra_fileds.update(user_activities) + extra_fields.update(user_activities) super().__init__( - logger_name=app_settings.USER_ACTIVITY_LOG, extra_fileds=extra_fileds + logger_name=app_settings.USER_ACTIVITY_LOG, extra_fields=extra_fields ) diff --git a/apps/content/scheduler/cleanup_document_job.py b/apps/content/scheduler/cleanup_document_job.py index 9e185ff..77a9e68 100644 --- a/apps/content/scheduler/cleanup_document_job.py +++ b/apps/content/scheduler/cleanup_document_job.py @@ -11,10 +11,6 @@ async def cleanup_document_job(): document_manager = DocumentManager() - # Monitor execution time - start_time = logging.getLogger().handlers[0].formatter.converter() - logging.info(f"Job started at {start_time}") - await document_manager.cleanup_document() logging.info("Successfully completed cleanup document job.") diff --git a/apps/content/webapi/bootstrap/application.py b/apps/content/webapi/bootstrap/application.py index 8e14dcd..7d0b26d 100644 --- a/apps/content/webapi/bootstrap/application.py +++ b/apps/content/webapi/bootstrap/application.py @@ -3,7 +3,8 @@ from fastapi import FastAPI from fastapi.openapi.utils import get_openapi from webapi.providers import common -from webapi.providers import logger + +from webapi.providers.logger import register_logger from webapi.providers import router from webapi.providers import database from webapi.providers import scheduler @@ -16,9 +17,9 @@ def create_app() -> FastAPI: app = FreeleapsApp() + register_logger() register(app, exception_handler) register(app, database) - register(app, logger) register(app, router) register(app, scheduler) register(app, common) diff --git a/apps/content/webapi/providers/logger.py b/apps/content/webapi/providers/logger.py index 4a3f1e7..afcab10 100644 --- a/apps/content/webapi/providers/logger.py +++ b/apps/content/webapi/providers/logger.py @@ -1,60 +1,47 @@ import logging import sys -from loguru import logger -from common.config.log_settings import log_settings +from loguru import logger as guru_logger -def register(app=None): - level = log_settings.LOG_LEVEL - file_path = log_settings.LOG_PATH - retention = log_settings.LOG_RETENTION - rotation = log_settings.LOG_ROTATION +def register_logger(): + print("📢 Setting up logging interception...") - # intercept everything at the root logger + # 🔴 **Ensure Uvicorn Logs Are Captured** + intercept_loggers = ["uvicorn", "uvicorn.access", "uvicorn.error", "fastapi"] + + class InterceptHandler(logging.Handler): + def emit(self, record): + level = ( + guru_logger.level(record.levelname).name + if guru_logger.level(record.levelname, None) + else record.levelno + ) + frame, depth = logging.currentframe(), 2 + while frame.f_code.co_filename == logging.__file__: + frame = frame.f_back + depth += 1 + + guru_logger.opt(depth=depth, exception=record.exc_info).log( + level, + f"[{record.name}] {record.getMessage()}", + ) + + # 🔴 **Replace Existing Loggers with Interception** + logging.root.handlers.clear() + logging.root.setLevel(logging.INFO) logging.root.handlers = [InterceptHandler()] - logging.root.setLevel(level) - # remove every other logger's handlers - # and propagate to root logger - for name in logging.root.manager.loggerDict.keys(): - logging.getLogger(name).handlers = [] - logging.getLogger(name).propagate = True + for logger_name in intercept_loggers: + logging_logger = logging.getLogger(logger_name) + logging_logger.handlers.clear() # Remove Uvicorn default handlers + logging_logger.propagate = True # ✅ Ensure they propagate through Loguru - # configure loguru - logger.add( - sink=sys.stdout - ) - logger.add( - sink=file_path, - level=level, - retention=retention, - rotation=rotation + # 🔴 **Redirect stdout/stderr to Loguru (Keep Green Timestamps)** + guru_logger.remove() + guru_logger.add( + sys.stdout, + level="INFO", + format="{time:YYYY-MM-DD HH:mm:ss.SSS} | {level} | {message}", ) - logger.disable("pika.adapters") - logger.disable("pika.connection") - logger.disable("pika.channel") - logger.disable("pika.callback") - logger.disable("pika.frame") - logger.disable("pika.spec") - logger.disable("aiormq.connection") - logger.disable("urllib3.connectionpool") - - -class InterceptHandler(logging.Handler): - def emit(self, record): - # Get corresponding Loguru level if it exists - try: - level = logger.level(record.levelname).name - except ValueError: - level = record.levelno - - # Find caller from where originated the logged message - frame, depth = logging.currentframe(), 2 - while frame.f_code.co_filename == logging.__file__: - frame = frame.f_back - depth += 1 - - logger.opt(depth=depth, exception=record.exc_info).log( - level, record.getMessage() - ) + print("✅ Logging interception complete. Logs are formatted and deduplicated!")