Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reduce verbosity of reconnection #933

Merged
merged 3 commits into from
Sep 4, 2024

Conversation

elupus
Copy link
Collaborator

@elupus elupus commented Jul 24, 2024

  • Reduce the verbosity of reconnection
  • Make sure write errors log the original exception

- Reduce the verbosity of reconnection
- Make sure write errors log the original exception
@@ -649,16 +650,16 @@ def _check_connection(self) -> bool:
# check if connection is expired
reset = False
if self._force_recon:
self.logger.warning(
"[%s(%s):%s] Error communicating with socket, resetting connection",
self.logger.debug(
Copy link
Collaborator

Choose a reason for hiding this comment

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

Debug is too low level, let's do info

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

All places that set force_recon have already logged an error

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Also this log is rather useless, below low where it is increased would be more usefull.

ogger: pychromecast.socket_client
Källa: /usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py:655
Inträffade först: 25 augusti 2024 kl. 02:00:06 (41 händelser)
Senast loggade: 19:26:34

[Announce Group(192.168.16.29):32096] Error communicating with socket, resetting connection
[Hela Huset(192.168.16.27):32053] Error communicating with socket, resetting connection
[Home Kök(192.168.16.29):8009] Error communicating with socket, resetting connection
[Cast Bibliotek(192.168.16.152):8009] Error communicating with socket, resetting connection
[65OLED855/12(192.168.16.36):8009] Error communicating with socket, resetting connection

self.fn or "",
self.host,
self.port,
)
reset = True

elif self.heartbeat_controller.is_expired():
self.logger.warning(
self.logger.debug(
Copy link
Collaborator

Choose a reason for hiding this comment

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

Same

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Missing heartbeat and reconnecting is not an issue we need to log (info could be okey). We only need to warn if we fail to reconnect.

Copy link
Collaborator Author

@elupus elupus Aug 30, 2024

Choose a reason for hiding this comment

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

Also.. We will be getting these anyway if there is a real problem om reconnect:

Logger: pychromecast.socket_client
Källa: /usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py:412
Inträffade först: 25 augusti 2024 kl. 02:00:35 (62 händelser)
Senast loggade: 19:26:34

[Home Kök(192.168.16.29):8009] Failed to connect to service HostServiceInfo(host='192.168.16.29', port=8009), retrying in 5.0s
[Nest Kontor(192.168.16.180):8009] Failed to connect to service HostServiceInfo(host='192.168.16.180', port=8009), retrying in 5.0s
[65OLED855/12(192.168.16.36):8009] Failed to connect to service HostServiceInfo(host='192.168.16.36', port=8009), retrying in 5.0s
[Cast Bibliotek(192.168.16.152):8009] Failed to connect to service HostServiceInfo(host='192.168.16.152', port=8009), retrying in 5.0s
[65OLED855/12(192.168.16.36):8009] Failed to connect to service MDNSServiceInfo(name='TPM191E-9d097cde37f733c13536e0f70255ccac._googlecast._tcp.local.'), retrying in 5.0s

if callback_function:
callback_function(False, None)
if not no_add_request_id:
self._request_callbacks.pop(request_id, None)
self._force_recon = True
self.logger.info(
"[%s(%s):%s] Error writing to socket.",
self.logger.warning(
Copy link
Collaborator

Choose a reason for hiding this comment

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

Why do we increase the severity here?

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

This is a real error. It should not log secondarily due to force recon.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Ps. This could also be some valid disconnection, which we likely should just info log. But if that is the case we can figure out that later.

@elupus
Copy link
Collaborator Author

elupus commented Sep 3, 2024

@emontnemery ok like this?

Copy link
Collaborator

@emontnemery emontnemery left a comment

Choose a reason for hiding this comment

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

Thanks @elupus 👍

@emontnemery emontnemery merged commit 93c7350 into home-assistant-libs:master Sep 4, 2024
1 check passed
@Hadatko
Copy link

Hadatko commented Oct 3, 2024

Hello, is this fixing

System log:
{"event_type":"system_log_event","event":{"name":"pychromecast.socket_client","message":["[Living Room TV(192.168.1.155):8009] Failed to connect to service HostServiceInfo(host='192.168.1.155', port=8009), retrying in 5.0s"],"level":"ERROR","source":["/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py",412],"timestamp":1727949273.2699394,"exception":"","count":1,"first_occurred":1727949273.2699394},"origin":"LOCAL","time_fired":"2024-10-03T09:54:33.271117+00:00","context":{"id":"01J98WTY5QKK2N1A6AP8Z2K32Y","parent_id":null,"user_id":null}}
🖥 System log:
{"event_type":"system_log_event","event":{"name":"pychromecast.socket_client","message":["[Living Room TV(192.168.1.155):8009] Heartbeat timeout, resetting connection"],"level":"WARNING","source":["/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py",664],"timestamp":1727970838.3446555,"exception":"","count":1,"first_occurred":1727970838.3446555},"origin":"LOCAL","time_fired":"2024-10-03T15:53:58.345110+00:00","context":{"id":"01J99HD1T9A1EMZ2WCFN79MG3Z","parent_id":null,"user_id":null}}

I am spammed with a lot of these messages. Everytime when i turn off my tv. And every 6h when tv is off as it is doing some short action by itself.. I would like to decrease level to debug for this reason (or other solution if possible).
If this is fixed when it will be released?

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.

4 participants