From e77bde4cebb7974f6ef36fce01525918d811c74a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=D9=8A?= Date: Thu, 12 Mar 2026 15:07:24 +0530 Subject: [PATCH] Unify backend logging and capture uncaught exceptions --- backend/logging_config.py | 135 ++++++++++++++++++++++++++++--- backend/start_alwrity_backend.py | 3 +- 2 files changed, 124 insertions(+), 14 deletions(-) diff --git a/backend/logging_config.py b/backend/logging_config.py index 539db62e..c809da20 100644 --- a/backend/logging_config.py +++ b/backend/logging_config.py @@ -3,19 +3,115 @@ Provides clean logging setup for end users vs developers. """ +import asyncio import logging import os import sys from loguru import logger +class InterceptHandler(logging.Handler): + """Route standard logging records into Loguru.""" + + def emit(self, record): + try: + level = logger.level(record.levelname).name + except ValueError: + level = record.levelno + + frame, depth = logging.currentframe(), 2 + while frame and frame.f_code.co_filename == logging.__file__: + frame = frame.f_back + depth += 1 + + logger.bind(logger_name=record.name).opt( + depth=depth, + exception=record.exc_info, + ).log(level, record.getMessage()) + + +def _patch_record_context(record): + """Ensure common context keys exist in every log record.""" + extra = record["extra"] + extra.setdefault("request_id", "-") + extra.setdefault("job_id", "-") + extra.setdefault("user_id", "-") + + +def _uncaught_exception_hook(exc_type, exc_value, exc_traceback): + """Capture any uncaught top-level exception with traceback.""" + if issubclass(exc_type, KeyboardInterrupt): + sys.__excepthook__(exc_type, exc_value, exc_traceback) + return + + logger.opt(exception=(exc_type, exc_value, exc_traceback)).critical( + "Uncaught exception reached sys.excepthook" + ) + + +def _asyncio_exception_handler(loop, context): + """Capture unhandled asyncio task/loop exceptions.""" + exception = context.get("exception") + message = context.get("message", "Unhandled asyncio exception") + + if exception: + logger.opt(exception=(type(exception), exception, exception.__traceback__)).critical( + "{}", message + ) + else: + logger.critical("{} | context={}", message, context) + + +def _register_global_exception_handlers(): + """Register global hooks for uncaught runtime exceptions.""" + sys.excepthook = _uncaught_exception_hook + + try: + policy = asyncio.get_event_loop_policy() + + class LoggingEventLoopPolicy(type(policy)): + def new_event_loop(self): + loop = super().new_event_loop() + loop.set_exception_handler(_asyncio_exception_handler) + return loop + + asyncio.set_event_loop_policy(LoggingEventLoopPolicy()) + except Exception: + logger.exception("Failed to install asyncio event loop policy") + + try: + loop = asyncio.get_event_loop() + loop.set_exception_handler(_asyncio_exception_handler) + except Exception: + # No active loop yet; policy above will handle future loops. + pass + + +def _configure_uvicorn_loggers(log_level): + """Route uvicorn loggers through the same handlers and format as Loguru.""" + intercept_handler = InterceptHandler() + + for name in ("uvicorn", "uvicorn.error", "uvicorn.access"): + uvicorn_logger = logging.getLogger(name) + uvicorn_logger.handlers = [intercept_handler] + uvicorn_logger.propagate = False + uvicorn_logger.setLevel(log_level) + + def setup_clean_logging(): """Set up clean logging for end users.""" verbose_mode = os.getenv("ALWRITY_VERBOSE", "false").lower() == "true" - + # Always remove all existing handlers first to prevent conflicts logger.remove() - + logger.configure(patcher=_patch_record_context) + + common_format = ( + "{time:HH:mm:ss} | {level: <8} | req={extra[request_id]} " + "job={extra[job_id]} user={extra[user_id]} | " + "{name}:{function}:{line} - {message}\n{exception}" + ) + if not verbose_mode: # Suppress verbose logging for end users - be more aggressive logging.getLogger('sqlalchemy.engine').setLevel(logging.CRITICAL) @@ -24,16 +120,16 @@ def setup_clean_logging(): logging.getLogger('sqlalchemy.orm').setLevel(logging.CRITICAL) logging.getLogger('sqlalchemy').setLevel(logging.CRITICAL) logging.getLogger('sqlalchemy.engine.Engine').setLevel(logging.CRITICAL) - + # Suppress service initialization logs logging.getLogger('services').setLevel(logging.WARNING) logging.getLogger('api').setLevel(logging.WARNING) logging.getLogger('models').setLevel(logging.WARNING) - + # Suppress specific noisy loggers noisy_loggers = [ 'linkedin_persona_service', - 'facebook_persona_service', + 'facebook_persona_service', 'core_persona_service', 'persona_analysis_service', 'ai_service_manager', @@ -79,10 +175,10 @@ def setup_clean_logging(): 'pricing_service', 'create_billing_tables' ] - + for logger_name in noisy_loggers: logging.getLogger(logger_name).setLevel(logging.WARNING) - + # Configure loguru to be less verbose (only show warnings and errors) def warning_only_filter(record): return record["level"].name in ["WARNING", "ERROR", "CRITICAL"] @@ -90,9 +186,12 @@ def warning_only_filter(record): logger.add( sys.stdout.write, level="WARNING", - format="{time:HH:mm:ss} | {level: <8} | {name}:{function}:{line} - {message}\n", - filter=warning_only_filter + format=common_format, + filter=warning_only_filter, + backtrace=True, + diagnose=True, ) + # Add a focused sink to surface Story Video Generation INFO logs in console def video_generation_filter(record): msg = record.get("message", "") @@ -105,20 +204,30 @@ def video_generation_filter(record): or service == "video_generation_service" or "services.llm_providers.main_video_generation" in name ) + logger.add( sys.stdout.write, level="INFO", - format="{time:HH:mm:ss} | {level: <8} | {name}:{function}:{line} - {message}\n", - filter=video_generation_filter + format=common_format, + filter=video_generation_filter, + backtrace=True, + diagnose=True, ) + uvicorn_level = logging.WARNING else: # In verbose mode, show all log levels with detailed formatting logger.add( sys.stdout.write, level="DEBUG", - format="{time:HH:mm:ss} | {level: <8} | {name}:{function}:{line} - {message}\n" + format=common_format, + backtrace=True, + diagnose=True, ) - + uvicorn_level = logging.DEBUG + + _configure_uvicorn_loggers(uvicorn_level) + _register_global_exception_handlers() + return verbose_mode diff --git a/backend/start_alwrity_backend.py b/backend/start_alwrity_backend.py index 58286dd6..96680239 100644 --- a/backend/start_alwrity_backend.py +++ b/backend/start_alwrity_backend.py @@ -278,7 +278,8 @@ def start_backend(enable_reload=False, production_mode=False): "scripts/*", "alwrity_utils/*" ], - log_level=uvicorn_log_level + log_level=uvicorn_log_level, + log_config=None ) except KeyboardInterrupt: