logging_utils.py

import logging
import sys
import time
import uuid
from contextlib import contextmanager
from contextvars import ContextVar

request_id_ctx: ContextVar[str] = ContextVar("request_id", default="-")


class RequestIdFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        record.request_id = request_id_ctx.get()
        return True


def setup_logging() -> None:
    # Windows' default console codepage (cp1252) can't encode characters
    # like em-dashes, which silently mangles log lines into "?" — force
    # UTF-8 on the underlying stream so any log message just works.
    if hasattr(sys.stdout, "reconfigure"):
        sys.stdout.reconfigure(encoding="utf-8")
    handler = logging.StreamHandler()
    handler.setFormatter(
        logging.Formatter("%(asctime)s [%(request_id)s] %(levelname)s %(message)s")
    )
    handler.addFilter(RequestIdFilter())

    logger = logging.getLogger("arxiv2code")
    logger.setLevel(logging.INFO)
    logger.handlers.clear()
    logger.addHandler(handler)
    logger.propagate = False


logger = logging.getLogger("arxiv2code")


def new_request_id() -> str:
    return uuid.uuid4().hex[:12]


@contextmanager
def log_external_call(name: str):
    """Wrap any external dependency call (arXiv API, PDF download, LLM
    call) for consistent duration + status logging. This is how you
    debug a 3am failure without being there: grep the request_id,
    see exactly which external call failed, how long it ran before
    failing, and what the exception was."""
    start = time.monotonic()
    logger.info(f"{name} started")
    try:
        yield
    except Exception as exc:
        duration = time.monotonic() - start
        logger.error(f"{name} FAILED after {duration:.2f}s: {type(exc).__name__}: {exc}")
        raise
    else:
        duration = time.monotonic() - start
        logger.info(f"{name} succeeded in {duration:.2f}s")