Harden logging config with safer overrides and optional JSON/file sinks

backend/api/linkedin_image_generation.py

@@ -2,7 +2,6 @@ from fastapi import APIRouter, HTTPException, UploadFile, File, Depends
 from pydantic import BaseModel
 from typing import List, Optional, Dict, Any
 import json
-import logging
 
 # Import our LinkedIn image generation services
 from services.linkedin.image_generation import LinkedInImageGenerator, LinkedInImageStorage
@@ -11,8 +10,7 @@ from services.onboarding.api_key_manager import APIKeyManager
 from middleware.auth_middleware import get_current_user
 
 # Set up logging
-logging.basicConfig(level=logging.INFO)
+from loguru import logger
-logger = logging.getLogger(__name__)
 
 # Initialize router
 router = APIRouter(prefix="/api/linkedin", tags=["linkedin-image-generation"])

backend/app.py

@@ -49,8 +49,8 @@ load_dotenv(project_root / '.env')  # root .env (fallback)
 load_dotenv()  # CWD .env (fallback)
 
 # Set up clean logging for end users
-from logging_config import setup_clean_logging
+from logging_config import configure_logging
-setup_clean_logging()
+configure_logging(bootstrap_source="asgi-import")
 
 # Import middleware
 from middleware.auth_middleware import get_current_user

backend/logging_config.py

@@ -1,128 +1,298 @@
-"""
+"""Centralized, production-ready logging configuration for the ALwrity backend."""
-Logging configuration for ALwrity backend.
-Provides clean logging setup for end users vs developers.
-"""
 
+from __future__ import annotations
+
+import asyncio
+import json
 import logging
 import os
 import sys
+from typing import Dict, Optional, Tuple
+
 from loguru import logger
 
+_LOGGING_CONFIGURED = False
 
-def setup_clean_logging():
+DEFAULT_LOG_OVERRIDES: Dict[str, str] = {
-    """Set up clean logging for end users."""
+    "sqlalchemy": "ERROR",
-    verbose_mode = os.getenv("ALWRITY_VERBOSE", "false").lower() == "true"
+    "sqlalchemy.engine": "ERROR",
+    "sqlalchemy.pool": "ERROR",
+    "uvicorn.access": "WARNING",
+    "watchfiles": "WARNING",
+    "httpx": "WARNING",
+    "urllib3": "WARNING",
+    "apscheduler": "INFO",
+}
 
-    # Always remove all existing handlers first to prevent conflicts
+VIDEO_SERVICE_NAMES = {
+    "video_generation_service",
+    "services.story_writer.video_generation_service",
+    "services.llm_providers.main_video_generation",
+}
+
+
+class InterceptHandler(logging.Handler):
+    """Forward standard-library logging records into Loguru sinks."""
+
+    def emit(self, record: logging.LogRecord) -> None:
+        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
+
+        stdlib_extra = {
+            key: value
+            for key, value in record.__dict__.items()
+            if key
+            not in {
+                "name", "msg", "args", "levelname", "levelno", "pathname", "filename",
+                "module", "exc_info", "exc_text", "stack_info", "lineno", "funcName",
+                "created", "msecs", "relativeCreated", "thread", "threadName", "processName",
+                "process", "message", "asctime"
+            }
+        }
+
+        log = logger.bind(stdlib_logger=record.name, **stdlib_extra)
+        log.opt(depth=depth, exception=record.exc_info).log(level, record.getMessage())
+
+
+def _env_bool(name: str, default: bool = False) -> bool:
+    value = os.getenv(name)
+    if value is None:
+        return default
+    return value.strip().lower() in {"1", "true", "yes", "on"}
+
+
+def _parse_level_overrides() -> Dict[str, str]:
+    overrides = dict(DEFAULT_LOG_OVERRIDES)
+    raw_overrides = os.getenv("ALWRITY_LOG_LEVEL_OVERRIDES", "").strip()
+    if not raw_overrides:
+        return overrides
+
+    for pair in raw_overrides.split(","):
+        pair = pair.strip()
+        if not pair or "=" not in pair:
+            continue
+        logger_name, level = pair.split("=", 1)
+        logger_name = logger_name.strip()
+        level = level.strip().upper()
+        if logger_name and level:
+            overrides[logger_name] = level
+
+    return overrides
+
+
+def _resolve_log_level(level_name: str, default: int = logging.INFO) -> Tuple[int, bool]:
+    try:
+        return logging._checkLevel(level_name), True
+    except (TypeError, ValueError):
+        return default, False
+
+
+def _apply_logger_overrides(verbose_mode: bool) -> None:
+    root_level = logging.DEBUG if verbose_mode else logging.INFO
+    logging.getLogger().setLevel(root_level)
+
+    for logger_name, level_name in _parse_level_overrides().items():
+        level_no, valid = _resolve_log_level(level_name)
+        if not valid:
+            logger.warning(
+                "Invalid log level override '{}' for logger '{}'; defaulting to INFO",
+                level_name,
+                logger_name,
+            )
+        logging.getLogger(logger_name).setLevel(level_no)
+
+
+def _serialize_record(record: Dict) -> str:
+    payload = {
+        "time": record["time"].isoformat(),
+        "level": record["level"].name,
+        "name": record["name"],
+        "function": record["function"],
+        "line": record["line"],
+        "message": record["message"],
+        "extra": record.get("extra", {}),
+    }
+    if record.get("exception"):
+        payload["exception"] = str(record["exception"])
+    return json.dumps(payload, default=str)
+
+
+def _base_log_format(verbose_mode: bool) -> str:
+    if verbose_mode:
+        return (
+            "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | "
+            "<level>{level: <8}</level> | "
+            "<cyan>{name}</cyan>:<cyan>{function}</cyan>:<cyan>{line}</cyan> | "
+            "rid={extra[request_id]} jid={extra[job_id]} uid={extra[user_id]} | "
+            "{message}"
+        )
+
+    return (
+        "<green>{time:HH:mm:ss}</green> | "
+        "<level>{level: <8}</level> | "
+        "<cyan>{name}</cyan>:<cyan>{line}</cyan> | "
+        "{message}"
+    )
+
+
+def _patch_record(record: Dict) -> Dict:
+    extra = record.setdefault("extra", {})
+    extra.setdefault("request_id", "-")
+    extra.setdefault("job_id", "-")
+    extra.setdefault("user_id", "-")
+    return record
+
+
+def _video_generation_filter(record: Dict) -> bool:
+    message = record.get("message", "")
+    name = record.get("name", "")
+    service_name = record.get("extra", {}).get("service")
+    return (
+        "[StoryVideoGeneration]" in message
+        or "[video_gen]" in message
+        or service_name in VIDEO_SERVICE_NAMES
+        or any(service in name for service in VIDEO_SERVICE_NAMES)
+    )
+
+
+def _configure_loguru_sinks(verbose_mode: bool) -> None:
     logger.remove()
 
-    if not verbose_mode:
+    logger.configure(patcher=_patch_record)
-        # Suppress verbose logging for end users - be more aggressive
-        logging.getLogger('sqlalchemy.engine').setLevel(logging.CRITICAL)
-        logging.getLogger('sqlalchemy.pool').setLevel(logging.CRITICAL)
-        logging.getLogger('sqlalchemy.dialects').setLevel(logging.CRITICAL)
-        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
+    log_json = _env_bool("ALWRITY_LOG_JSON", default=False)
-        logging.getLogger('services').setLevel(logging.WARNING)
+    console_format = _serialize_record if log_json else _base_log_format(verbose_mode)
-        logging.getLogger('api').setLevel(logging.WARNING)
-        logging.getLogger('models').setLevel(logging.WARNING)
 
-        # Suppress specific noisy loggers
+    logger.add(
-        noisy_loggers = [
+        sys.stdout,
-            'linkedin_persona_service',
+        level="DEBUG" if verbose_mode else "WARNING",
-            'facebook_persona_service', 
+        format=console_format,
-            'core_persona_service',
+        backtrace=True,
-            'persona_analysis_service',
+        diagnose=verbose_mode,
-            'ai_service_manager',
+        enqueue=True,
-            'ai_engine_service',
+    )
-            'website_analyzer',
-            'competitor_analyzer',
-            'keyword_researcher',
-            'content_gap_analyzer',
-            'onboarding_data_service',
-            'comprehensive_user_data',
-            'strategy_data',
-            'gap_analysis_data',
-            'phase1_steps',
-            'daily_schedule_generator',
-            'gsc_service',
-            'wordpress_oauth',
-            'data_filter',
-            'source_mapper',
-            'grounding_engine',
-            'blog_content_seo_analyzer',
-            'linkedin_service',
-            'citation_manager',
-            'content_analyzer',
-            'linkedin_prompt_generator',
-            'linkedin_image_storage',
-            'hallucination_detector',
-            'writing_assistant',
-            'onboarding_data_service',
-            'enhanced_linguistic_analyzer',
-            'persona_quality_improver',
-            'logging_middleware',
-            'exa_service',
-            'step3_research_service',
-            'sitemap_service',
-            'linkedin_image_generator',
-            'linkedin_prompt_generator',
-            'linkedin_image_storage',
-            'router_manager',
-            'frontend_serving',
-            'database',
-            'user_business_info',
-            'auth_middleware',
-            '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"]
 
+    enable_video_focus = _env_bool("ALWRITY_ENABLE_VIDEO_LOG_FOCUS", default=not verbose_mode)
+    if enable_video_focus and not verbose_mode:
         logger.add(
-            sys.stdout.write,
+            sys.stdout,
-            level="WARNING",
-            format="{time:HH:mm:ss} | {level: <8} | {name}:{function}:{line} - {message}\n",
-            filter=warning_only_filter
-        )
-        # Add a focused sink to surface Story Video Generation INFO logs in console
-        def video_generation_filter(record):
-            msg = record.get("message", "")
-            name = record.get("name", "")
-            service = record.get("extra", {}).get("service")
-            return (
-                "[StoryVideoGeneration]" in msg
-                or "services.story_writer.video_generation_service" in name
-                or "[video_gen]" in msg
-                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",
+            format=console_format,
-            filter=video_generation_filter
+            filter=_video_generation_filter,
-        )
+            enqueue=True,
-    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"
         )
 
+    log_file = os.getenv("ALWRITY_LOG_FILE", "").strip()
+    if log_file:
+        logger.add(
+            log_file,
+            level="DEBUG" if verbose_mode else "INFO",
+            format=console_format,
+            rotation=os.getenv("ALWRITY_LOG_ROTATION", "50 MB"),
+            retention=os.getenv("ALWRITY_LOG_RETENTION", "14 days"),
+            enqueue=True,
+            backtrace=True,
+            diagnose=verbose_mode,
+        )
+
+
+def _configure_stdlib_intercept(verbose_mode: bool) -> None:
+    intercept_handler = InterceptHandler()
+    root_logger = logging.getLogger()
+    root_logger.handlers = [intercept_handler]
+    root_logger.setLevel(logging.DEBUG if verbose_mode else logging.INFO)
+
+    for name in ("uvicorn", "uvicorn.error", "uvicorn.access", "gunicorn", "gunicorn.error"):
+        target_logger = logging.getLogger(name)
+        target_logger.handlers = [intercept_handler]
+        target_logger.propagate = False
+
+    logging.captureWarnings(True)
+
+
+def _register_exception_hooks() -> None:
+    def _excepthook(exc_type, exc_value, exc_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")
+
+    def _async_exception_handler(loop, context):
+        exc = context.get("exception")
+        if exc:
+            logger.opt(exception=exc).error("Unhandled asyncio exception")
+        else:
+            logger.error("Unhandled asyncio exception: {}", context.get("message", context))
+
+    sys.excepthook = _excepthook
+
+    try:
+        loop = asyncio.get_running_loop()
+        loop.set_exception_handler(_async_exception_handler)
+    except RuntimeError:
+        pass
+
+
+def configure_logging(*, verbose_mode: Optional[bool] = None, force: bool = False, bootstrap_source: str = "unknown") -> bool:
+    """Configure Loguru + stdlib logging in one place.
+
+    Environment variables:
+        - ALWRITY_VERBOSE=true|false
+        - ALWRITY_LOG_LEVEL_OVERRIDES="sqlalchemy=ERROR,uvicorn.access=WARNING"
+        - ALWRITY_ENABLE_VIDEO_LOG_FOCUS=true|false
+        - ALWRITY_LOG_JSON=true|false
+        - ALWRITY_LOG_FILE=/path/to/backend.log
+        - ALWRITY_LOG_ROTATION=50 MB
+        - ALWRITY_LOG_RETENTION=14 days
+    """
+    global _LOGGING_CONFIGURED
+
+    if _LOGGING_CONFIGURED and not force:
+        return os.getenv("ALWRITY_VERBOSE", "false").lower() == "true"
+
+    if verbose_mode is None:
+        verbose_mode = _env_bool("ALWRITY_VERBOSE", default=False)
+
+    os.environ["ALWRITY_VERBOSE"] = "true" if verbose_mode else "false"
+
+    _configure_loguru_sinks(verbose_mode)
+    _configure_stdlib_intercept(verbose_mode)
+    _apply_logger_overrides(verbose_mode)
+    _register_exception_hooks()
+
+    logger.bind(source=bootstrap_source).info(
+        "Logging configured (verbose={}, source={})",
+        verbose_mode,
+        bootstrap_source,
+    )
+
+    _LOGGING_CONFIGURED = True
     return verbose_mode
 
 
-def get_uvicorn_log_level():
+
-    """Get appropriate uvicorn log level based on verbose mode."""
+def bind_logger_context(*, request_id: Optional[str] = None, job_id: Optional[str] = None, user_id: Optional[str] = None):
-    verbose_mode = os.getenv("ALWRITY_VERBOSE", "false").lower() == "true"
+    """Return a context-bound logger for request/job/user correlation."""
+    return logger.bind(
+        request_id=request_id or "-",
+        job_id=job_id or "-",
+        user_id=user_id or "-",
+    )
+
+
+def setup_clean_logging() -> bool:
+    """Backward-compatible wrapper for existing imports."""
+    return configure_logging(bootstrap_source="setup_clean_logging")
+
+
+def get_uvicorn_log_level() -> str:
+    """Get uvicorn log level based on verbose mode."""
+    verbose_mode = _env_bool("ALWRITY_VERBOSE", default=False)
     return "debug" if verbose_mode else "warning"

backend/main.py

@@ -49,8 +49,8 @@ load_dotenv(project_root / '.env')  # root .env (fallback)
 load_dotenv()  # CWD .env (fallback)
 
 # Set up clean logging for end users
-from logging_config import setup_clean_logging
+from logging_config import configure_logging
-setup_clean_logging()
+configure_logging(bootstrap_source="asgi-import")
 
 # Import middleware
 from middleware.auth_middleware import get_current_user

backend/services/llm_providers/gemini_provider.py

@@ -76,7 +76,6 @@ else:
     load_dotenv()
     print(f"No .env found at {env_path}, using current directory")
 
-from loguru import logger
 from utils.logger_utils import get_service_logger
 
 # Use service-specific logger to avoid conflicts
@@ -93,10 +92,6 @@ import re
 
 from typing import Optional, Dict, Any
 
-# Configure standard logging
-import logging
-logging.basicConfig(level=logging.INFO, format='[%(asctime)s-%(levelname)s-%(module)s-%(lineno)d]- %(message)s')
-logger = logging.getLogger(__name__)
 
 def get_gemini_api_key() -> str:
     """Get Gemini API key with proper error handling."""

backend/start_alwrity_backend.py

@@ -216,7 +216,7 @@ def start_backend(enable_reload=False, production_mode=False):
         print("=" * 50)
         
         # Set up clean logging for end users
-        from logging_config import setup_clean_logging, get_uvicorn_log_level
+        from logging_config import configure_logging, get_uvicorn_log_level
         # Video stack preflight (diagnostics + version assert)
         try:
             from services.story_writer.video_preflight import (
@@ -228,7 +228,7 @@ def start_backend(enable_reload=False, production_mode=False):
             log_video_stack_diagnostics = None
             assert_supported_moviepy = None
         
-        verbose_mode = setup_clean_logging()
+        verbose_mode = configure_logging(verbose_mode=verbose_mode, bootstrap_source="start_alwrity_backend")
         uvicorn_log_level = get_uvicorn_log_level()
 
         # Log diagnostics and assert versions (fail fast if misconfigured)