Skip to content

Error logging is broken: rich handler raises ModuleNotFoundError on emit, so asyncio exceptions are swallowed and only a logger traceback survives #978

Description

@olegbrok

Found during a routine overnight log scan, 2026-08-02 ~01:10 PDT. Error logging in the running daemon is broken, and it fails in the way that destroys the evidence.

Symptom

Exception ignored in: <bound method BaseEventLoop.call_exception_handler ...>
Traceback (most recent call last):
  .../asyncio/base_events.py:1818 in call_exception_handler
    logger.error('Exception in default exception handler', ...)
  .../logging/__init__.py:1518 → _log → handle → callHandlers → hdlr.handle → emit
  /Users/oleg/PinkyBot/.venv/lib/python3.11/site-packages/rich/logging.py:150 in emit
ModuleNotFoundError: No module named 'rich.traceback'

An asyncio exception reaches the default handler, the handler calls logger.error, the rich log handler's emit raises on import rich.traceback, and Python discards the whole thing — "Exception ignored in:".

The original exception is never recorded. What lands in the log is a traceback about the logger, not about whatever actually failed. Three occurrences in the current (post-rotation) log alone, so this is ongoing rather than a one-off.

This is the worst version of a failure we keep hitting: the mechanism that would tell us something broke is the thing that's broken, and its own failure looks like unrelated noise.

What I verified

  • .venv/bin/python -c "import rich"ModuleNotFoundError: No module named 'rich'. Not a partial package — rich is absent entirely.
  • .venv/lib/python3.11/site-packages/rich/traceback.py → does not exist.
  • But the traceback cites .venv/lib/python3.11/site-packages/rich/logging.py:150, so rich/logging.py did exist in that venv when the error was raised, and the package has since gone (or was always incomplete and is now fully gone).
  • The daemon is otherwise healthy and serving requests normally.

What I did NOT determine — do not inherit these as facts

  • Whether the running daemon's interpreter is this .venv. The traceback's package path says yes, but I did not check the live process's sys.path.
  • When or why rich disappeared — partial uninstall, an interrupted reinstall, a dependency resolution that dropped it, or an install in flight while I looked.
  • Whether anything besides the asyncio default handler routes through the rich handler.

⚠️ Inconsistency with #961 worth resolving

#961 reports ModuleNotFoundError: No module named 'sqlite_vec' in this daemon. But sqlite_vec imports fine from .venv right now:

.venv/bin/python -c "import sqlite_vec"   → OK

So either #961 is already fixed, or the failing code runs under a different interpreter than .venv, or the failure is environmental/subprocess-scoped. Two missing-module errors in the same daemon where one module is demonstrably present is a strong hint that the real issue is which interpreter the daemon actually runs, not which packages are installed — which would make #961 and this issue the same root cause wearing two names.

That is the thing to check first, and it is cheap: get the live process's executable and sys.path.

Why it matters tonight

Overnight automation (3am dream, 4am autoupdate, 4am soup) runs unattended. If any of it raises through an asyncio handler, the detail is discarded and the morning evidence is a logger traceback. Combined with #962 (owner-notify delivery failing) and #402 (chez pager is a placeholder), that is three independent paths by which a failure can occur and nobody is told — this one being the most fundamental, since it loses the error rather than merely failing to forward it.

Not an outage; the daemon works. But it is an observability hole exactly where observability is load-bearing.


🤖 Filed by Barsik

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions