fix: FCM watchdog observability — demote spurious WARNING, log swallowed restart errors (v0.16.5-beta.1) - #17
Merged
Conversation
…restart errors Observability follow-up to the FCM reconnect-storm hardening (v0.16.4-beta.2, 15f7d58); the restart state machine is unchanged. - Log the restart scheduling at INFO instead of WARNING: is_started() is also False during seconds-long transient states (socket resets, initial connection), so a watchdog tick landing inside one emitted a recurring, alarming WARNING that the next healthy tick silently cleared. WARNING is now reserved for the restart actually firing. Scheduling is intentionally NOT gated on transient run states: a client stuck in STARTING_CONNECTION after exhausting initial retries (zombie mode) must remain visible to the watchdog. - Broaden the restart catch in ensure_running() to Exception with _LOGGER.exception: the register() path can raise types beyond connection errors, and the watchdog gathers with return_exceptions=True and discards results, so escaped exceptions vanished without a log line. - Return the success of the start call instead of is_started (usually still False while the fresh client connects), matching the documented contract. - Rate-limit filter: ignore exc_info == (None, None, None) (exc_info=True outside an except block) so it neither consumes throttle budget nor gains the "traceback suppressed" suffix. Adds coverage for the transient reset window (no WARNING, no restart), unexpected restart exceptions, the still-connecting return value, and the None-tuple exc_info case. Closes #16
anthonws
added a commit
to anthonws/fermax-blue-hass
that referenced
this pull request
Jul 4, 2026
… (v0.13.0) Addresses 46 findings from a multi-agent performance/reliability/security audit. Highlights below; each change is annotated with its audit id in-code. ## Performance — stream startup latency (the headline) - Video now goes live independently of the ~10s Fermax "pickup": the video relay + frame grabber + is_active are started right after the video consumer, and the audio relay is pre-created from a silent switchable source so its m-line is negotiated up front. When pickup completes, the real intercom audio is swapped into that relay — no WebRTC renegotiation. Cuts perceived first-frame latency from ~13s to ~3-4s (bvis#2, bvis#6). - Frame grabber: decode+JPEG-encode moved off the event loop via to_thread, encoded once (overlay burned in) instead of twice, and throttled to ~5fps when not recording since the WebRTC path consumes raw relay frames (bvis#3,bvis#7,bvis#8). - WebRTC offer handler polls the relay at 0.1s (was 0.5s) and caps ICE gathering at 4s (was 10s) (bvis#18, bvis#19). ## Reliability - CRITICAL: re-register a rotated FCM token with Fermax. Previously a token rotation silently killed the doorbell until a full reload (bvis#1). - Notification de-duplication now persists persistent_ids across restarts, so FCM re-deliveries are recognised by id; the blunt 10s time-grace is used only on first run — a genuine ring right after restart is no longer dropped (bvis#9,bvis#24). - Serialise stream start/stop with a lock + session-identity guards so overlapping notifications can't orphan a half-started session; the grabber's end-callback no longer clobbers a newer session; stop() is idempotent and the session is fully torn down on natural end (bvis#11, bvis#26, bvis#27, bvis#45). - FCM decrypt: escalate to ERROR after 5 consecutive failures (systemic outage) instead of masking it as healthy (bvis#10). - Socket.IO connect() is bounded by a 15s timeout; startup HTTP calls carry an explicit per-request timeout (bvis#13, bvis#30). - Partial-setup teardown: a later pairing failing no longer leaks earlier coordinators' FCM listeners / API client (bvis#14). - Auto-stop timer defers while a card viewer is connected (G3); call_mode and stream_duration persist across restarts via RestoreEntity (G2). - Camera closes in-flight PCs on unload; lock cancels its auto-lock timer on removal; send_audio resolves coordinators dynamically and is unregistered on the last unload; shared API client closed once (bvis#12, G5, G4, G7). - Misc: recv() raises MediaStreamError not StopIteration; get_running_loop; access-token / credentials-save / callDate parse hardened (bvis#29,bvis#28,bvis#31,bvis#33,bvis#39). ## Security / hardening - TLS enforcement uses a urlparse allowlist and rejects whitespace, closing the " http://…" leading-space bypass; signaling URL must be https/wss on *.fermax.io (bvis#16, bvis#37). - Diagnostics redacts all Firebase identifiers + OAuth tokens; log redaction recurses into lists; join_call errors no longer logged verbatim (bvis#35,bvis#34,bvis#36). - send_audio and auto-response file paths validated before av.open (bvis#38); recording temp files already use mkstemp; ffmpeg shell=False. - Rate-limit log filter is now thread-safe (bvis#44). ## Custom Lovelace card (v1.1.1) - Mic is never acquired during idle polling (no OS mic-indicator flicker); talkback is enabled on demand via a mic-inclusive sendrecv reconnect, which is how a single-offer server negotiates outbound audio (bvis#5). - Epoch guard prevents PC/subscription leaks when the card is removed mid- connect; synchronous re-entrancy lock stops duplicate connects; explicit hangup no longer auto-reconnects; aspect_ratio is sanitised (bvis#4,bvis#17,bvis#40,bvis#41). ## Dependencies - Declare av>=11 and numpy>=1.20 (used on core streaming paths; permissive bounds satisfied by HA, no re-conflict with the av 17 situation) (G1). Deferred (negligible/intentional): per-frame relay list copy (bvis#22), in-memory recording buffer bounded by auto-stop (bvis#23), FCM restart backoff by design (bvis#25), minor stop() sleeps (bvis#42), reload token ordering (bvis#43). Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Closes #16. Observability follow-up to the FCM reconnect-storm hardening shipped in #14 (v0.16.4-beta.2). The restart state machine is unchanged.
Changes
is_started()is alsoFalseduring seconds-long transient states (RESETTING,STARTING_*— e.g. routine upstream socket resets), so a 60 s watchdog tick landing inside one logged a recurring, alarmingWARNING: FCM listener is not running; restart scheduled…that the next healthy tick silently cleared. WARNING is now reserved for the moment the restart actually fires. Scheduling is intentionally not gated on transient run states: a client stuck inSTARTING_CONNECTIONafter exhausting initial retries (zombie mode) must stay visible to the watchdog.ensure_running()caught only(ConnectionError, OSError, RuntimeError), but theregister()path can raise other types; combined with the watchdog'sreturn_exceptions=Truegather discarding results, a failed restart attempt left no log line at all. The catch is nowExceptionwith_LOGGER.exception(...).ensure_running()returnedis_startedright after a successful restart, which is usuallyFalsewhile the fresh client is still connecting — contradicting the docstring. It now returns the success of the start call.exc_info == (None, None, None)(a truthy tuple, produced byexc_info=Trueoutside anexceptblock) no longer consumes throttle budget nor gains the "(traceback suppressed)" suffix.Tests
4 new tests (18 total in
test_notification.py, 154 overall):ValueError) → returnsFalse, logged with traceback, not propagated.True.exc_info=(None, None, None)record → passes untouched, budget intact.Release
Version bumped to 0.16.5-beta.1 per the beta-first release workflow; promote to 0.16.5 stable after verifying on live HA.
make pre-push(full CI replica, py3.12 + py3.13) passes.