diff --git a/backend/api/linkedin_image_generation.py b/backend/api/linkedin_image_generation.py index 0bf77270..1848c0bf 100644 --- a/backend/api/linkedin_image_generation.py +++ b/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) -logger = logging.getLogger(__name__) +from loguru import logger # Initialize router router = APIRouter(prefix="/api/linkedin", tags=["linkedin-image-generation"]) diff --git a/backend/app.py b/backend/app.py index 0b190fb9..15712d87 100644 --- a/backend/app.py +++ b/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 -setup_clean_logging() +from logging_config import configure_logging +configure_logging(bootstrap_source="asgi-import") # Import middleware from middleware.auth_middleware import get_current_user diff --git a/backend/logging_config.py b/backend/logging_config.py index 539db62e..4e9bccd3 100644 --- a/backend/logging_config.py +++ b/backend/logging_config.py @@ -1,128 +1,298 @@ -""" -Logging configuration for ALwrity backend. -Provides clean logging setup for end users vs developers. -""" +"""Centralized, production-ready logging configuration for the ALwrity backend.""" +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(): - """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() - - if not verbose_mode: - # 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 - 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', - 'core_persona_service', - 'persona_analysis_service', - 'ai_service_manager', - '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"] +DEFAULT_LOG_OVERRIDES: Dict[str, str] = { + "sqlalchemy": "ERROR", + "sqlalchemy.engine": "ERROR", + "sqlalchemy.pool": "ERROR", + "uvicorn.access": "WARNING", + "watchfiles": "WARNING", + "httpx": "WARNING", + "urllib3": "WARNING", + "apscheduler": "INFO", +} - logger.add( - sys.stdout.write, - 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 +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 ( + "{time:YYYY-MM-DD HH:mm:ss.SSS} | " + "{level: <8} | " + "{name}:{function}:{line} | " + "rid={extra[request_id]} jid={extra[job_id]} uid={extra[user_id]} | " + "{message}" + ) + + return ( + "{time:HH:mm:ss} | " + "{level: <8} | " + "{name}:{line} | " + "{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() + + logger.configure(patcher=_patch_record) + + log_json = _env_bool("ALWRITY_LOG_JSON", default=False) + console_format = _serialize_record if log_json else _base_log_format(verbose_mode) + + logger.add( + sys.stdout, + level="DEBUG" if verbose_mode else "WARNING", + format=console_format, + backtrace=True, + diagnose=verbose_mode, + enqueue=True, + ) + + 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="INFO", - format="{time:HH:mm:ss} | {level: <8} | {name}:{function}:{line} - {message}\n", - filter=video_generation_filter + format=console_format, + filter=_video_generation_filter, + enqueue=True, ) - else: - # In verbose mode, show all log levels with detailed formatting + + log_file = os.getenv("ALWRITY_LOG_FILE", "").strip() + if log_file: logger.add( - sys.stdout.write, - level="DEBUG", - format="{time:HH:mm:ss} | {level: <8} | {name}:{function}:{line} - {message}\n" + 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.""" - verbose_mode = os.getenv("ALWRITY_VERBOSE", "false").lower() == "true" + +def bind_logger_context(*, request_id: Optional[str] = None, job_id: Optional[str] = None, user_id: Optional[str] = None): + """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" diff --git a/backend/main.py b/backend/main.py index 7f5ee43f..f6b59c61 100644 --- a/backend/main.py +++ b/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 -setup_clean_logging() +from logging_config import configure_logging +configure_logging(bootstrap_source="asgi-import") # Import middleware from middleware.auth_middleware import get_current_user diff --git a/backend/services/llm_providers/gemini_provider.py b/backend/services/llm_providers/gemini_provider.py index 6d40aa78..eb470473 100644 --- a/backend/services/llm_providers/gemini_provider.py +++ b/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.""" diff --git a/backend/start_alwrity_backend.py b/backend/start_alwrity_backend.py index 58286dd6..e297e13d 100644 --- a/backend/start_alwrity_backend.py +++ b/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)