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

[sammywachtel]

Why

On a server, one unhandled exception in an API request takes 15-20 seconds of CPU to log, and on a small VM it took over a minute. The work runs on the event loop, so no other request is answered until it finishes. A client sees its own request time out, and every other client of that process sees everything stall.

The cause is diagnose=True on the file and stdout sinks in setup_logging. With diagnose, loguru calls repr() on every value named in every frame of a logged traceback, synchronously. The API's catch-all handler (api/app.py, exception_handler) logs with logger.exception, and the traceback of a request runs through about thirty ASGI middleware frames, each holding scope. Under FastAPI 0.139, repr(scope) is very large, because its "fastapi" entry carries the route's dependency tree.

Evidence

Measured on current main, in-process, with the test app from tests/api/v2/conftest.py, on a request that raised inside POST /v2/projects/{id}/knowledge/resolve:

• repr(scope): 158,454,847 characters, 0.53 s. The "fastapi" entry alone accounts for 158,452,963 of those characters.
• The whole request, with the production sinks installed, answered its 500 after 19.42 s.

On a server process, I profiled one such request with py-spy (1,877 samples). Of the 1,539 main-thread samples, 1,516 were under exception_handler → loguru._logger.exception → _better_exceptions._format_exception → _get_relevant_values → _format_value, and 1,188 were in dataclass __repr__. py-spy dump --locals showed the value being formatted was the ASGI scope dict, recursing through _IncludedRouter → _EffectiveRouteContext → Dependant. A concurrent request to the same process waited 13.4 s.

The backend makes no difference. SQLite and Postgres both took about 15 s, and the database was idle throughout.

What changed

• setup_logging: the file sink and the stdout sink use diagnose=False. backtrace=True stays, so the full traceback is still logged. Only the dump of each frame's variable values is gone.
• Test mode (BASIC_MEMORY_ENV=test) keeps diagnose=True, so local test failures still show values.

Testing

• New tests/api/v2/test_unhandled_exception_logging.py, both of which fail on main:
  • test_a_logged_traceback_does_not_repr_frame_values: with the production sinks installed, logging one traceback calls repr() on a frame value 0 times. On main: assert 4 == 0.
  • test_an_unhandled_request_exception_answers_fast: a real unhandled exception through the real app, with the production sinks installed, answers its 500 in under 2 s. On main: one unhandled exception took 19.42s to answer. With this change: about 0.2 s.
• tests/api/v2, tests/utils, tests/test_telemetry.py: 540 passed. All 39 errors are in tests/api/v2/test_scoped_search_router.py (SemanticSearchDisabledError, which comes from this machine's environment). They also occur on unchanged main.
• ruff format, ruff check, ty check src tests test-int (with the milvus extra installed): clean.
• Not run: the Postgres suites.

Risks / follow-ups

• Server logs lose the per-frame variable values that diagnose printed. Those values are also a privacy risk on a server, because they can carry request bodies, headers and note content into the log file. The traceback itself is unchanged.
• Any exception that is predictable should still be handled at its route rather than reaching the catch-all handler.
• The cost of repr(scope) comes from FastAPI's internals, so a future FastAPI release could make it larger or smaller. With diagnose=False the cost no longer depends on it.