fix(core): log tracebacks without per-frame values on the long-lived sinks

src/basic_memory/utils.py

@@ -502,6 +502,14 @@ def setup_logging(
         logger.add(sys.stderr, level=log_level, backtrace=True, diagnose=True, colorize=True)
         return
 
+    # Trigger: a traceback is logged while a request is being handled, for example by the
+    #   API's catch-all exception handler.
+    # Why: diagnose=True calls repr() on every value named in every frame of the traceback,
+    #   synchronously. Each ASGI middleware frame holds `scope`, and under FastAPI 0.139
+    #   repr(scope) is about 190 MB (its "fastapi" entry carries the route's dependency
+    #   tree), so one unhandled exception costs seconds of CPU on the event loop.
+    # Outcome: the long-lived sinks keep the full traceback (backtrace=True) and drop the
+    #   per-frame value dump. Test mode above keeps diagnose=True.
     # Add file handler with rotation
     if log_to_file:
         # Trigger: Windows does not allow renaming an open file held by another process.
@@ -524,14 +532,14 @@ def setup_logging(
             rotation="10 MB",
             retention=5,
             backtrace=True,
-            diagnose=True,
+            diagnose=False,
             enqueue=False,
             colorize=False,
         )
 
     # Add stdout handler (for Docker/cloud)
     if log_to_stdout:
-        logger.add(sys.stderr, level=log_level, backtrace=True, diagnose=True, colorize=True)
+        logger.add(sys.stderr, level=log_level, backtrace=True, diagnose=False, colorize=True)
 
     # Add Logfire sink when telemetry bootstrap enabled it for this process.
     logfire_handler = telemetry.get_logfire_handler()

tests/api/v2/test_unhandled_exception_logging.py

@@ -0,0 +1,100 @@
+"""Logging an unhandled request exception must cost milliseconds, not seconds.
+
+With loguru's `diagnose=True`, logging a traceback calls repr() on every value named in
+every frame. Each ASGI middleware frame holds `scope`, and under FastAPI 0.139
+repr(scope) is about 190 MB, so one unhandled exception spent seconds of CPU on the event
+loop while every other request waited.
+"""
+
+from __future__ import annotations
+
+import time
+from typing import override
+
+import pytest
+from fastapi import FastAPI
+from httpx import ASGITransport, AsyncClient
+from loguru import logger
+
+from basic_memory import utils
+from basic_memory.deps.services import get_link_resolver_v2_external
+
+#: About 0.05 s with this change, about 10-20 s without it on a laptop.
+CEILING_SECONDS = 2.0
+
+
+@pytest.fixture
+def production_sinks(monkeypatch, tmp_path):
+    """The file and stdout sinks a deployed process uses, and nothing else.
+
+    The test run's own sink is set up in test mode, which keeps diagnose=True, so every
+    handler is removed for the test and the test-mode setup is restored afterwards.
+    """
+    monkeypatch.setenv("BASIC_MEMORY_ENV", "dev")
+    monkeypatch.setenv("BASIC_MEMORY_CONFIG_DIR", str(tmp_path))
+    monkeypatch.setattr(utils.telemetry, "get_logfire_handler", lambda: None)
+    utils.setup_logging(log_to_file=True, log_to_stdout=True)
+    try:
+        yield tmp_path / "basic-memory.log"
+    finally:
+        monkeypatch.setenv("BASIC_MEMORY_ENV", "test")
+        utils.setup_logging()
+
+
+class _CountedRepr:
+    reprs = 0
+
+    @override
+    def __repr__(self) -> str:
+        type(self).reprs += 1
+        return "<counted>"
+
+
+def test_a_logged_traceback_does_not_repr_frame_values(production_sinks):
+    _CountedRepr.reprs = 0
+
+    def fails(value):
+        raise RuntimeError(f"boom {id(value)}")
+
+    def handler():
+        held = _CountedRepr()
+        try:
+            fails(held)
+        except RuntimeError:
+            logger.exception("unhandled")
+
+    handler()
+
+    assert _CountedRepr.reprs == 0
+    text = production_sinks.read_text()
+    # The traceback is still logged; only the per-frame value dump is gone.
+    assert "Traceback" in text and "RuntimeError: boom" in text
+
+
+@pytest.mark.asyncio
+async def test_an_unhandled_request_exception_answers_fast(
+    app: FastAPI, v2_project_url, production_sinks
+):
+    class ExplodingResolver:
+        async def resolve_entity(self, *args, **kwargs):
+            raise RuntimeError("resolver exploded")
+
+        resolve_link = resolve_entity
+
+    app.dependency_overrides[get_link_resolver_v2_external] = lambda: ExplodingResolver()
+    try:
+        async with AsyncClient(
+            transport=ASGITransport(app=app, raise_app_exceptions=False),
+            base_url="http://test",
+        ) as client:
+            started = time.perf_counter()
+            response = await client.post(
+                f"{v2_project_url}/knowledge/resolve", json={"identifier": "anything"}
+            )
+            elapsed = time.perf_counter() - started
+    finally:
+        app.dependency_overrides.pop(get_link_resolver_v2_external, None)
+
+    assert response.status_code == 500
+    assert "resolver exploded" in production_sinks.read_text()
+    assert elapsed < CEILING_SECONDS, f"one unhandled exception took {elapsed:.2f}s to answer"