Skip to content

fix(connection): log routine event connection loss at DEBUG - #45

Open
GreenGrassBlueOcean wants to merge 1 commit into
OpenWebNet-HA:masterfrom
GreenGrassBlueOcean:fix/event-session-reconnect-debug-logging
Open

GreenGrassBlueOcean wants to merge 1 commit into
OpenWebNet-HA:masterfrom
GreenGrassBlueOcean:fix/event-session-reconnect-debug-logging

Conversation

@GreenGrassBlueOcean

Copy link
Copy Markdown
Contributor

Summary

Follows up on real-world testing feedback from @marcob79 in OpenWebNet-HA/MyHOME#304.

In OWNEventSession.get_next(), when a socket EOF (asyncio.IncompleteReadError) or connection drop (ConnectionResetError, OSError) occurs:

  • Previously, OWNd logged this at WARNING level:
    self._logger.warning("%s Event connection lost, reconnecting...", self._log_id)
  • Gateways such as the MH200/MH201 enforce a hard 1-hour (3,600-second) session lifetime limit on TCP connections. Even when the bus is actively running commands, the gateway cleanly terminates the session every hour.
  • OWNd catches this and transparently recovers within ~8 ms with zero frame loss.
  • However, because the log was at WARNING level, downstream consumers like Home Assistant surfaced an alarming warning banner in Settings → System → Logs every hour on the hour, leading users to believe the connection was unhealthy or unstable.

This PR demotes the routine disconnect log to DEBUG.

Failure Behavior

Actual failure conditions remain fully reported:

  • If the subsequent _reconnect() fails, line 1106 already logs at WARNING:
    self._logger.warning("%s Reconnection failed; next attempt in %ss.", self._log_id, pause)
  • Fatal negotiation and authentication errors continue to be handled and reported.
  • Downstream integrations (like MyHOME) continue to track availability grace periods (60 s) and warn if an outage actually persists.

Changes

  • OWNd/connection.py: Log routine event session connection loss at DEBUG instead of WARNING.
  • tests/test_connection.py: Added test_event_connection_loss_is_logged_at_debug asserting logger.debug is invoked and logger.warning is not called on connection loss.

@codecov-commenter

Copy link
Copy Markdown

⚠️ Please install the 'codecov app svg image' to ensure uploads and comments are reliably processed by Codecov.

Codecov Report

✅ All modified and coverable lines are covered by tests.

📢 Thoughts on this report? Let us know!

@fedem95 fedem95 left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Confirmed on my physical MH201 (b13 + OWNd b8, running for 30 h): 30 event session drops, all recovered, zero "Reconnection failed" and zero availability warnings downstream. The demotion is justified.
On my hardware the reconnect occurs every ~57 min 40s.

Two suggestions for this PR:

  • a flapping session is now completely silent as long as each reconnect succeeds. Until we know the per-model cadence, a burst rule would be model-agnostic: warn when drops cluster, say three within ten minutes, then at most once an hour.
  • asyncio.LimitOverrunError shares this except block. An over-long or garbage frame is not a routine session recycle; hiding it at DEBUG loses a real protocol signal. I would keep that one at WARNING.

Failure paths still log properly (Event session not connected + Reconnection failed), tests pass locally and CI is green.

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.

3 participants