Enhance logging with exception handlers and context tracking
- Add InterceptHandler to route stdlib logging to Loguru - Add _patch_record_context for request/job/user ID tracking - Add _uncaught_exception_hook to capture top-level exceptions - Add _asyncio_exception_handler for asyncio task exceptions - Add _register_global_exception_handlers to register all hooks - Add _configure_uvicorn_loggers for unified uvicorn logging - Improve log format with contextual fields (req, job, user)
This commit is contained in:
@@ -3,21 +3,114 @@ Logging configuration for ALwrity backend.
|
|||||||
Provides clean logging setup for end users vs developers.
|
Provides clean logging setup for end users vs developers.
|
||||||
"""
|
"""
|
||||||
|
|
||||||
|
import asyncio
|
||||||
import logging
|
import logging
|
||||||
import os
|
import os
|
||||||
import sys
|
import sys
|
||||||
from loguru import logger
|
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:
|
||||||
|
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():
|
def setup_clean_logging():
|
||||||
"""Set up clean logging for end users."""
|
"""Set up clean logging for end users."""
|
||||||
verbose_mode = os.getenv("ALWRITY_VERBOSE", "false").lower() == "true"
|
verbose_mode = os.getenv("ALWRITY_VERBOSE", "false").lower() == "true"
|
||||||
|
|
||||||
# Always remove all existing handlers first to prevent conflicts
|
|
||||||
logger.remove()
|
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:
|
if not verbose_mode:
|
||||||
# Suppress verbose logging for end users - be more aggressive
|
|
||||||
logging.getLogger('sqlalchemy.engine').setLevel(logging.CRITICAL)
|
logging.getLogger('sqlalchemy.engine').setLevel(logging.CRITICAL)
|
||||||
logging.getLogger('sqlalchemy.pool').setLevel(logging.CRITICAL)
|
logging.getLogger('sqlalchemy.pool').setLevel(logging.CRITICAL)
|
||||||
logging.getLogger('sqlalchemy.dialects').setLevel(logging.CRITICAL)
|
logging.getLogger('sqlalchemy.dialects').setLevel(logging.CRITICAL)
|
||||||
@@ -25,12 +118,10 @@ def setup_clean_logging():
|
|||||||
logging.getLogger('sqlalchemy').setLevel(logging.CRITICAL)
|
logging.getLogger('sqlalchemy').setLevel(logging.CRITICAL)
|
||||||
logging.getLogger('sqlalchemy.engine.Engine').setLevel(logging.CRITICAL)
|
logging.getLogger('sqlalchemy.engine.Engine').setLevel(logging.CRITICAL)
|
||||||
|
|
||||||
# Suppress service initialization logs
|
|
||||||
logging.getLogger('services').setLevel(logging.WARNING)
|
logging.getLogger('services').setLevel(logging.WARNING)
|
||||||
logging.getLogger('api').setLevel(logging.WARNING)
|
logging.getLogger('api').setLevel(logging.WARNING)
|
||||||
logging.getLogger('models').setLevel(logging.WARNING)
|
logging.getLogger('models').setLevel(logging.WARNING)
|
||||||
|
|
||||||
# Suppress specific noisy loggers
|
|
||||||
noisy_loggers = [
|
noisy_loggers = [
|
||||||
'linkedin_persona_service',
|
'linkedin_persona_service',
|
||||||
'facebook_persona_service',
|
'facebook_persona_service',
|
||||||
@@ -61,7 +152,6 @@ def setup_clean_logging():
|
|||||||
'linkedin_image_storage',
|
'linkedin_image_storage',
|
||||||
'hallucination_detector',
|
'hallucination_detector',
|
||||||
'writing_assistant',
|
'writing_assistant',
|
||||||
'onboarding_data_service',
|
|
||||||
'enhanced_linguistic_analyzer',
|
'enhanced_linguistic_analyzer',
|
||||||
'persona_quality_improver',
|
'persona_quality_improver',
|
||||||
'logging_middleware',
|
'logging_middleware',
|
||||||
@@ -69,8 +159,6 @@ def setup_clean_logging():
|
|||||||
'step3_research_service',
|
'step3_research_service',
|
||||||
'sitemap_service',
|
'sitemap_service',
|
||||||
'linkedin_image_generator',
|
'linkedin_image_generator',
|
||||||
'linkedin_prompt_generator',
|
|
||||||
'linkedin_image_storage',
|
|
||||||
'router_manager',
|
'router_manager',
|
||||||
'frontend_serving',
|
'frontend_serving',
|
||||||
'database',
|
'database',
|
||||||
@@ -83,17 +171,18 @@ def setup_clean_logging():
|
|||||||
for logger_name in noisy_loggers:
|
for logger_name in noisy_loggers:
|
||||||
logging.getLogger(logger_name).setLevel(logging.WARNING)
|
logging.getLogger(logger_name).setLevel(logging.WARNING)
|
||||||
|
|
||||||
# Configure loguru to be less verbose (only show warnings and errors)
|
|
||||||
def warning_only_filter(record):
|
def warning_only_filter(record):
|
||||||
return record["level"].name in ["WARNING", "ERROR", "CRITICAL"]
|
return record["level"].name in ["WARNING", "ERROR", "CRITICAL"]
|
||||||
|
|
||||||
logger.add(
|
logger.add(
|
||||||
sys.stdout.write,
|
sys.stdout.write,
|
||||||
level="WARNING",
|
level="WARNING",
|
||||||
format="{time:HH:mm:ss} | {level: <8} | {name}:{function}:{line} - {message}\n",
|
format=common_format,
|
||||||
filter=warning_only_filter
|
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):
|
def video_generation_filter(record):
|
||||||
msg = record.get("message", "")
|
msg = record.get("message", "")
|
||||||
name = record.get("name", "")
|
name = record.get("name", "")
|
||||||
@@ -105,19 +194,28 @@ def setup_clean_logging():
|
|||||||
or service == "video_generation_service"
|
or service == "video_generation_service"
|
||||||
or "services.llm_providers.main_video_generation" in name
|
or "services.llm_providers.main_video_generation" in name
|
||||||
)
|
)
|
||||||
|
|
||||||
logger.add(
|
logger.add(
|
||||||
sys.stdout.write,
|
sys.stdout.write,
|
||||||
level="INFO",
|
level="INFO",
|
||||||
format="{time:HH:mm:ss} | {level: <8} | {name}:{function}:{line} - {message}\n",
|
format=common_format,
|
||||||
filter=video_generation_filter
|
filter=video_generation_filter,
|
||||||
|
backtrace=True,
|
||||||
|
diagnose=True,
|
||||||
)
|
)
|
||||||
|
uvicorn_level = logging.WARNING
|
||||||
else:
|
else:
|
||||||
# In verbose mode, show all log levels with detailed formatting
|
|
||||||
logger.add(
|
logger.add(
|
||||||
sys.stdout.write,
|
sys.stdout.write,
|
||||||
level="DEBUG",
|
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
|
return verbose_mode
|
||||||
|
|
||||||
|
|||||||
Reference in New Issue
Block a user