Skip to content

Stop re-formatting the same stream exception on every read-loop iteration - #39

Open
bvis wants to merge 1 commit into
sdb9696:mainfrom
bvis:fix/listen-repeated-read-exception-spin
Open

bvis wants to merge 1 commit into
sdb9696:mainfrom
bvis:fix/listen-repeated-read-exception-spin

Conversation

@bvis

@bvis bvis commented Jun 11, 2026

Copy link
Copy Markdown

Related to #23 and #33; complementary to #36 and #38 (different code path: this covers the generic "unexpected exception" branch that those PRs leave untouched).

Summary

When the MCS stream fails persistently, the _listen loop can re-format and log the same exception object on every iteration — and that exception's traceback grows on each raise, making the logging quadratically expensive inside the event loop.

Mechanism:

  1. asyncio's StreamReader stores a failed stream's exception and re-raises the SAME object on every subsequent read (asyncio/streams.py, raise self._exception), appending a few frames to its __traceback__ each time.
  2. A ConnectionResetError outside RESETTING state hits the generic else branch, which calls _logger.exception(...) — full traceback, every iteration.
  3. If _reset() early-returns (its lock is held, e.g. by the monitor task), the loop re-reads the poisoned reader with no suspending await → tight loop.
  4. On Python 3.13+ traceback formatting additionally runs ast.parse per frame (caret anchors), so formatting the growing chain dominates: observed in production as a CPU core pinned at 100% for >10 minutes inside the event loop.

Observed on a Home Assistant 2026.6.1 / Python 3.14 installation during a period when Google persistently reset the MCS session right after login: HA's event loop starved, the HTTP API died, and the OS watchdog kill-looped the process. py-spy dump of the hung process:

Thread 71 (active+gil)          ← MainThread / event loop
    parse (ast.py:46)
    _extract_caret_anchors_from_line_segment (traceback.py:842)
    format_frame_summary → format → print_exception
    formatException (logging/__init__.py:670)
    ...
    _listen (firebase_messaging/fcmpushclient.py:717)

Changes

  • Track the last exception seen by the read loop by identity. The first occurrence keeps today's behaviour (full logging.exception). Repeats of the same object are summarised through the existing _log_warn_with_limit helper (one line, no traceback) and the loop await asyncio.sleep(1)s so it can never spin hot on a poisoned reader. Error accounting (_try_increment_error_count / _reset) is unchanged in both paths.
  • tests/fakes.py: FakeReader.set_exception() mimics StreamReader's sticky-exception semantics so the failure mode is reproducible in tests.
  • Regression test asserting that with a persistently failing reader the full traceback is logged exactly once and the rate-limited summary line appears. The test fails on current main and passes with this change.

Testing

  • uv run pytest tests/test_fcmpushclient.py — 14 passed (13 existing + 1 new).
  • New test verified to fail without the fcmpushclient.py change.
  • ruff check / ruff format --check clean.

…tion

asyncio streams store a failed reader's exception and re-raise the SAME
object on every subsequent read, so its traceback grows by a few frames
per raise. The _listen loop logged the full (ever-growing) traceback on
every iteration via logging.exception; combined with Python 3.13+
fine-grained traceback formatting (ast.parse per frame for caret
anchors) this becomes quadratically expensive inside the event loop and
was observed pinning a CPU core and starving a Home Assistant instance
until its watchdog killed it.

Track the last exception seen by identity: the first occurrence keeps
today's full logging.exception, repeats of the same object are
summarised with the existing rate-limited warning helper and the loop
yields for a second so it can never spin hot on a poisoned reader.

The FakeReader gains StreamReader-faithful sticky-exception semantics
(set_exception) to reproduce the failure mode in tests.
bvis added a commit to bvis/aegis-hass that referenced this pull request Jun 14, 2026
When the upstream reconnect-storm fix (sdb9696/firebase-messaging#39) ships and
the requirement is bumped, the local hardening should be re-evaluated. Add code
anchors at the dependency pin (pyproject.toml) and the guard module so the
reminder fires at the point of action; manifest.json is JSON (no comments) and
stays the version source of truth. Tracked in #297.
@bvis

bvis commented Jul 20, 2026

Copy link
Copy Markdown
Author

Hi, is anything I could do?

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant