routstr-core/routstr/core/logging.py

"""
Logging configuration for Routstr.

CRITICAL LOG MESSAGES FOR USAGE STATISTICS:
===========================================
The following log messages are parsed by the usage tracking system
(routstr/core/usage_analytics_store.py and routstr/core/log_manager.py).
DO NOT modify or remove these messages without updating the usage tracking logic:

1. "Received proxy request" (INFO) - routstr/proxy.py
   - Used to count total incoming requests
   - Includes model information in context

2. "Calculated token-based cost" (INFO) - routstr/auth.py
   - Used to track successful completions and revenue
   - The 'token_cost', 'model', 'input_tokens', and 'output_tokens' fields are extracted for dashboard metrics

3. "Max cost payment finalized" (INFO) - routstr/auth.py
   - Used as the successful completion fallback when token usage is unavailable
   - The 'charged_amount', 'model', 'input_tokens', and 'output_tokens' fields are extracted for dashboard metrics

4. "Payment processed successfully" (INFO) - routstr/auth.py
   - Used to count successful payment processing events
   - Tracks payment-related metrics

5. "Upstream request failed, revert payment" (WARNING) - routstr/proxy.py
   - Used to track failed requests and refunds
   - The 'max_cost_for_model' field is extracted for refund calculation
   - Must include 'max_cost_for_model' in extra dict

6. Any ERROR level logs with "upstream" in the message
   - Used to count upstream provider errors
   - Helps identify service reliability issues

If you need to modify these messages, ensure you also update the parsing logic in:
- routstr/core/usage_analytics_store.py
- routstr/core/log_manager.py
"""

import logging.config
import logging.handlers
import os
import re
import sys
import tomllib
from datetime import datetime
from pathlib import Path
from typing import Any

from pythonjsonlogger import jsonlogger
from rich.console import Console
from rich.logging import RichHandler

from .redaction import redact_field, redact_org_ids

# Only use RichHandler when stdout is a real TTY. In non-TTY contexts
# (docker logs, pipes, CI) Rich pads every line to width and wraps long
# records, producing visually-empty trailing whitespace and split records.
# A plain StreamHandler avoids both problems.
_stdout_is_tty = sys.stdout.isatty()
_console = Console(soft_wrap=True) if _stdout_is_tty else None

# Define custom TRACE level
TRACE_LEVEL = 5
logging.addLevelName(TRACE_LEVEL, "TRACE")


def trace(self: logging.Logger, message: str, *args: Any, **kwargs: Any) -> None:
    """Log with TRACE level"""
    if self.isEnabledFor(TRACE_LEVEL):
        self._log(TRACE_LEVEL, message, args, **kwargs)


# Add the trace method to Logger class
setattr(logging.Logger, "trace", trace)


class DailyRotatingFileHandler(logging.handlers.TimedRotatingFileHandler):
    """Custom TimedRotatingFileHandler that creates date-based filenames."""

    def __init__(self, filename: str, **kwargs: Any) -> None:
        """Initialize with a base filename pattern."""
        self.base_dir = os.path.dirname(filename)
        self.base_name = os.path.basename(filename).replace(".log", "")

        today = datetime.now().strftime("%Y-%m-%d")
        self.current_date = today
        dated_filename = os.path.join(self.base_dir, f"{self.base_name}_{today}.log")

        super().__init__(dated_filename, **kwargs)

    def doRollover(self) -> None:
        """Override rollover to create new date-based filename."""
        if self.stream:
            self.stream.close()

        new_date = datetime.now().strftime("%Y-%m-%d")
        new_filename = os.path.join(self.base_dir, f"{self.base_name}_{new_date}.log")

        self.baseFilename = new_filename
        self.current_date = new_date

        # `backupCount` alone never prunes these files: the base filename moves
        # with the date, so the inherited rollover finds no siblings to expire
        # and every day of logged credentials is retained indefinitely.
        self._cleanup_old_files()

        if not self.delay:
            self.stream = self._open()

    def _cleanup_old_files(self) -> None:
        """Remove old log files beyond backupCount."""
        if self.backupCount > 0:
            log_files = []
            if os.path.exists(self.base_dir):
                for file in os.listdir(self.base_dir):
                    if file.startswith(f"{self.base_name}_") and file.endswith(".log"):
                        file_path = os.path.join(self.base_dir, file)
                        log_files.append((file_path, os.path.getmtime(file_path)))

            log_files.sort(key=lambda x: x[1], reverse=True)

            for file_path, _ in log_files[self.backupCount :]:
                try:
                    os.remove(file_path)
                except OSError:
                    pass


def get_package_version() -> str:
    """Read the package version from pyproject.toml."""
    try:
        # Find project root by looking for pyproject.toml
        current_path = Path(__file__).parent
        while current_path != current_path.parent:
            pyproject_path = current_path / "pyproject.toml"
            if pyproject_path.exists():
                with open(pyproject_path, "rb") as f:
                    pyproject_data = tomllib.load(f)
                version = pyproject_data.get("project", {}).get("version", "unknown")
                return version
            current_path = current_path.parent

        # Fallback: try the simple path resolution (3 levels up for routstr/logging/logging_config.py)
        pyproject_path = Path(__file__).parent.parent.parent / "pyproject.toml"
        if pyproject_path.exists():
            with open(pyproject_path, "rb") as f:
                pyproject_data = tomllib.load(f)
            version = pyproject_data.get("project", {}).get("version", "unknown")
            return version

        return "unknown"
    except Exception:
        return "unknown"


class VersionFilter(logging.Filter):
    """Filter to add package version to all log records."""

    def __init__(self) -> None:
        super().__init__()
        self.version = get_package_version()

    def filter(self, record: logging.LogRecord) -> bool:
        """Add version information to the log record."""
        record.version = self.version
        return True


class RequestIdFilter(logging.Filter):
    """Filter to add request ID to all log records."""

    def filter(self, record: logging.LogRecord) -> bool:
        """Add request ID to the log record if available."""
        try:
            # Import here to avoid circular imports
            from .middleware import request_id_context

            request_id = request_id_context.get(None)
            record.request_id = request_id if request_id else "no-request-id"
        except ImportError:
            # If middleware isn't available yet, just use default
            record.request_id = "no-request-id"
        return True


# Standard ``LogRecord`` attributes that are never user-supplied ``extra``
# fields; skipped when redacting structured extras (``msg``/``message`` are
# handled separately above).
_NON_EXTRA_RECORD_ATTRS = frozenset(
    {
        "name",
        "msg",
        "args",
        "levelname",
        "levelno",
        "pathname",
        "filename",
        "module",
        "exc_info",
        "exc_text",
        "stack_info",
        "lineno",
        "funcName",
        "created",
        "msecs",
        "relativeCreated",
        "thread",
        "threadName",
        "processName",
        "process",
        "taskName",
        "message",
    }
)


class SecurityFilter(logging.Filter):
    """Filter to remove sensitive information from logs."""

    SENSITIVE_KEYS = {
        "authorization",
        "x-cashu",
        "bearer",
        "token",
        "key",
        "secret",
        "password",
        "cashu_token",
        "bearer_key",
        "api_key",
        "nsec",
        "upstream_api_key",
        "refund_address",
    }

    def filter(self, record: logging.LogRecord) -> bool:
        """Filter out sensitive information from log records."""
        try:
            message = record.getMessage()
            message = redact_org_ids(message)
            standalone_patterns = [
                r"Bearer\s+([a-zA-Z0-9_\-\.]{10,})",  # Bearer token (must be 10 characters or more to reduce false-positives)
                r"cashu[A-Z]+([a-zA-Z0-9_\-\.=/+]+)",  # Cashu tokens
                r"nsec[a-z0-9]+",  # Nostr Public / Private Key
            ]
            for pattern in standalone_patterns:
                message = re.sub(pattern, "[REDACTED]", message, flags=re.IGNORECASE)

            for key in self.SENSITIVE_KEYS:
                if key in message.lower():
                    key_patterns = [
                        rf"{key}\s*[:=]\s*([a-zA-Z0-9_\-\.=/+]+)",  # key:value or key=value (including any variant with spaces)
                        rf'{key}\s*[:=]\s*["\']([^"\']+)["\']',  # key:"value" or key='value' (including any variant with spaces)
                    ]
                    for pattern in key_patterns:
                        message = re.sub(
                            pattern, f"{key}: [REDACTED]", message, flags=re.IGNORECASE
                        )
            record.msg = message
            record.args = ()

            # Structured `extra={...}` fields are emitted by the JSON formatter
            # straight from the record dict and never pass through the message
            # formatting above, so they need their own recursive pass.
            for attr, value in list(record.__dict__.items()):
                if attr in _NON_EXTRA_RECORD_ATTRS:
                    continue
                record.__dict__[attr] = redact_field(attr, value)

        except Exception:
            pass

        return True


def get_log_level() -> str:
    """Get log level from environment variable."""
    try:
        from .settings import settings

        level = settings.log_level.upper()
    except Exception:
        level = os.environ.get("LOG_LEVEL", "INFO").upper()
    # Validate log level - if invalid, default to INFO
    valid_levels = {"TRACE", "DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"}
    if level not in valid_levels:
        level = "INFO"
    return level


def should_enable_console_logging() -> bool:
    """Check if console logging should be enabled."""
    try:
        from .settings import settings

        return bool(settings.enable_console_logging)
    except Exception:
        return os.environ.get("ENABLE_CONSOLE_LOGGING", "true").lower() in (
            "true",
            "1",
            "yes",
        )


def setup_logging() -> None:
    """Configure centralized logging for the application."""

    log_level = get_log_level()
    console_enabled = should_enable_console_logging()

    # Determine which handlers to use
    handlers = ["file"]
    if console_enabled:
        handlers.append("console")

    if _stdout_is_tty:
        console_handler: dict[str, Any] = {
            "()": RichHandler,
            "level": log_level,
            "show_time": False,
            "show_path": False,
            "rich_tracebacks": True,
            "markup": True,
            "console": _console,
            "filters": ["request_id_filter", "security_filter"],
        }
    else:
        console_handler = {
            "class": "logging.StreamHandler",
            "level": log_level,
            "formatter": "plain",
            "stream": "ext://sys.stdout",
            "filters": ["request_id_filter", "security_filter"],
        }

    LOGGING_CONFIG = {
        "version": 1,
        "disable_existing_loggers": False,
        "formatters": {
            "json": {
                "()": jsonlogger.JsonFormatter,
                "format": "%(asctime)s %(name)s %(levelname)s %(message)s %(pathname)s %(lineno)d %(version)s %(request_id)s",
                "datefmt": "%Y-%m-%d %H:%M:%S",
            },
            "plain": {
                "format": "%(asctime)s %(levelname)-7s %(name)s %(message)s",
                "datefmt": "%Y-%m-%d %H:%M:%S",
            },
        },
        "filters": {
            "version_filter": {"()": VersionFilter},
            "request_id_filter": {"()": RequestIdFilter},
            "security_filter": {"()": SecurityFilter},
        },
        "handlers": {
            "console": console_handler,
            "file": {
                "()": DailyRotatingFileHandler,
                "level": log_level,
                "formatter": "json",
                "filename": "logs/app.log",
                "when": "midnight",  # Rotate at midnight each day
                "interval": 1,  # Every 1 day
                "backupCount": 30,  # Keep 30 days of logs
                "atTime": None,  # Rotate at midnight (00:00)
                "filters": ["version_filter", "request_id_filter", "security_filter"],
            },
        },
        "loggers": {
            "routstr": {
                "level": log_level,
                "handlers": handlers,
                "propagate": False,
            },
            "routstr.payment": {
                "level": log_level,
                "handlers": handlers,
                "propagate": False,
            },
            "routstr.proxy": {
                "level": log_level,
                "handlers": handlers,
                "propagate": False,
            },
            "routstr.auth": {
                "level": log_level,
                "handlers": handlers,
                "propagate": False,
            },
            "routstr.payment.models": {
                "level": log_level,
                "handlers": handlers,
                "propagate": False,
            },
            "routstr.core.exceptions": {
                "level": log_level,
                "handlers": handlers,
                "propagate": False,
            },
            "routstr.core.middleware": {
                "level": log_level,
                "handlers": ["file"],
                "propagate": False,
            },
            # Suppress verbose third-party logging
            "httpx": {
                "level": "WARNING",
                "handlers": ["console"] if console_enabled else [],
                "propagate": False,
            },
            "openai": {
                "level": "WARNING",
                "handlers": ["console"] if console_enabled else [],
                "propagate": False,
            },
            "httpcore": {
                "level": "WARNING",
                "handlers": ["console"] if console_enabled else [],
                "propagate": False,
            },
            "websockets": {
                "level": "WARNING",
                "handlers": [],
                "propagate": False,
            },
            "uvicorn.access": {
                "level": "WARNING",
                "handlers": ["file"],
                "propagate": False,
            },
            "uvicorn.error": {
                "level": log_level,
                "handlers": handlers,
                "propagate": False,
            },
            "watchfiles.main": {"level": "WARNING", "handlers": [], "propagate": False},
            "aiosqlite": {"level": "ERROR", "handlers": [], "propagate": False},
            "alembic": {
                "level": "WARNING",
                "handlers": ["console"] if console_enabled else [],
                "propagate": False,
            },
        },
        "root": {
            "level": log_level,
            "handlers": ["console"] if console_enabled else [],
        },
    }

    os.makedirs("logs", exist_ok=True)

    logging.config.dictConfig(LOGGING_CONFIG)


def get_logger(name: str) -> logging.Logger:
    """Get a logger instance for the given module name."""
    return logging.getLogger(name)