search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
71.59k stars 29.91k forks source link

pychromecast causing Home Assistant to crash #111762

Closed jonferreira closed 6 months ago

jonferreira commented 6 months ago

The problem

Hi.

For quite some time now my HA randomly crashes taking the docker container with it.

It seems to be related to the pychromecast library used by HA to communicate with Google Chromecast.

Attached all the information I could gather. I can also share the homeassistant.log.fault file if needed (too large to copy paste here)

What version of Home Assistant Core has the issue?

core-2024.2.1

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

pychromecast

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Last Log entry before the crash:

2024-02-28 19:35:28.609 ERROR (Thread-13) [pychromecast.socket_client] [Living Room(192.168.1.141):8009] Unhandled exception in worker thread, attempting reconnect
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 815, in _read_bytes_from_socket
    chunk = self.socket.recv(min(msglen - bytes_recd, 2048))
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/ssl.py", line 1234, in recv
    return self.read(buflen)
           ^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/ssl.py", line 1107, in read
    return self._sslobj.read(len)
           ^^^^^^^^^^^^^^^^^^^^^^
ssl.SSLError: [SSL: SSLV3_ALERT_BAD_RECORD_MAC] sslv3 alert bad record mac (_ssl.c:2559)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 540, in run
    if self.run_once(timeout=POLL_TIME_BLOCKING) == 1:
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 598, in run_once
    message = self._read_message()
              ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 845, in _read_message
    payload_info = self._read_bytes_from_socket(4)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 831, in _read_bytes_from_socket
    if _is_ssl_timeout(exc):
       ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 123, in _is_ssl_timeout
    return exc.message in (
           ^^^^^^^^^^^
AttributeError: 'ssl.SSLError' object has no attribute 'message'
2024-02-28 19:35:28.631 WARNING (Thread-13) [pychromecast.socket_client] [Living Room(192.168.1.141):8009] Error communicating with socket, resetting connection

Additional information

No response

jonferreira commented 6 months ago

For what is worth I've just noticed 2024.3 will Bump pychromecast to 14.0.0 so maybe that will help, will have to wait for next stable release to test it

ClayBenson94 commented 6 months ago

For what is worth I've just noticed 2024.3 will Bump pychromecast to 14.0.0 so maybe that will help, will have to wait for next stable release to test it

@jonferreira Where do you see that? Poking through the beta release notes and I don't see that (but I might be lookin' in the wrong spot!)

home-assistant[bot] commented 6 months ago

Hey there @emontnemery, mind taking a look at this issue as it has been labeled with an integration (cast) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `cast` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign cast` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)

cast documentation cast source (message by IssueLinks)

jonferreira commented 6 months ago

For what is worth I've just noticed 2024.3 will Bump pychromecast to 14.0.0 so maybe that will help, will have to wait for next stable release to test it

@jonferreira Where do you see that? Poking through the beta release notes and I don't see that (but I might be lookin' in the wrong spot!)

there you go mate - https://rc.home-assistant.io/changelogs/core-2024.3

jonferreira commented 6 months ago

for what is worth I've now upgraded to 2024.3.1 and will report back if this happens again

emontnemery commented 6 months ago

The offending code was removed from pychromecast 14.0.0 which is part of Home Assistant Core 2024.3, so the exact same error can't happen again.

However, that error is extremely unlikely to have caused the Home Assistant Core process to crash; the log shows that the connection to the cast device was lost and then attempted to be reestablished.

jonferreira commented 6 months ago

Every single time that happened, HA crashed. For months.

That can't be a coincidence...

jonferreira commented 6 months ago

@emontnemery it happened again, sent a "TTS command" and docker container crashed :

2024-03-19 19:05:18.842 ERROR (Thread-13) [pychromecast.socket_client] [Living Room(192.168.1.141):8009] Unhandled exception in worker thread, attempting reconnect Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 533, in run if self._run_once(timeout=POLL_TIME_BLOCKING) == 1: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 591, in _run_once message = self._read_message() ^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 824, in _read_message payload_info = self._read_bytes_from_socket(4) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 806, in _read_bytes_from_socket chunk = self.socket.recv(min(msglen - bytes_recd, 2048)) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/ssl.py", line 1233, in recv return self.read(buflen) ^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/ssl.py", line 1106, in read return self._sslobj.read(len) ^^^^^^^^^^^^^^^^^^^^^^ ssl.SSLError: [SSL: SSLV3_ALERT_BAD_RECORD_MAC] sslv3 alert bad record mac (_ssl.c:2559) 2024-03-19 19:05:18.884 WARNING (Thread-13) [pychromecast.socket_client] [Living Room(192.168.1.141):8009] Error communicating with socket, resetting connection 2024-03-19 19:05:18.891 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140496672273088] Failed to execute set volume. Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 239, in handle_call_service response = await hass.services.async_call( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2319, in async_call response_data = await coro ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2356, in _execute_service return await target(service_call) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 905, in entity_service_call single_response = await _handle_entity_call( ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 975, in _handle_entity_call result = await task ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/media_player/__init__.py", line 812, in async_set_volume_level await self.hass.async_add_executor_job(self.set_volume_level, volume) File "/usr/local/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/cast/media_player.py", line 508, in set_volume_level self._get_chromecast().set_volume(volume) File "/usr/local/lib/python3.12/site-packages/pychromecast/controllers/receiver.py", line 256, in set_volume response_handler.wait_response() File "/usr/local/lib/python3.12/site-packages/pychromecast/response_handler.py", line 54, in wait_response raise RequestFailed(self._request) pychromecast.error.RequestFailed: Failed to execute set volume.

Let me know if you want me to send you home-assistant.log.fault

jonferreira commented 5 months ago

This happened again and as usual, docker container crashed immediately.

2024-04-07 14:53:12.004 ERROR (Thread-13) [pychromecast.socket_client] [Living Room(192.168.1.141):8009] Unhandled exception in worker thread, attempting reconnect Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 533, in run if self._run_once(timeout=POLL_TIME_BLOCKING) == 1: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 591, in _run_once message = self._read_message() ^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 824, in _read_message payload_info = self._read_bytes_from_socket(4) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 806, in _read_bytes_from_socket chunk = self.socket.recv(min(msglen - bytes_recd, 2048)) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/ssl.py", line 1233, in recv return self.read(buflen) ^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/ssl.py", line 1106, in read return self._sslobj.read(len) ^^^^^^^^^^^^^^^^^^^^^^ ssl.SSLError: [SSL: SSLV3_ALERT_BAD_RECORD_MAC] sslv3 alert bad record mac (_ssl.c:2559) 2024-04-07 14:53:12.025 WARNING (Thread-13) [pychromecast.socket_client] [Living Room(192.168.1.141):8009] Error communicating with socket, resetting connection

I'd really appreciate if you could take a look at this @emontnemery

dgikiller commented 4 months ago

:wave: Hello everyone, happy Tuesday! I was looking to see if there were more reports of this one after my HA restarted itself yesterday. I got the same error as the above in the evening with the latest 2024.5.1.

2024-05-06 22:05:08.945 ERROR (Thread-7) [pychromecast.socket_client] [Cucina(xxx.xxx.xxx.xxx):8009] Unhandled exception in worker thread, attempting reconnect
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 533, in run
    if self._run_once(timeout=POLL_TIME_BLOCKING) == 1:
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 591, in _run_once
    message = self._read_message()
              ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 824, in _read_message
    payload_info = self._read_bytes_from_socket(4)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py", line 806, in _read_bytes_from_socket
    chunk = self.socket.recv(min(msglen - bytes_recd, 2048))
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/ssl.py", line 1233, in recv
    return self.read(buflen)
           ^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/ssl.py", line 1106, in read
    return self._sslobj.read(len)
           ^^^^^^^^^^^^^^^^^^^^^^
ssl.SSLError: [SSL: SSLV3_ALERT_BAD_RECORD_MAC] sslv3 alert bad record mac (_ssl.c:2559)

This then caused a full restart of the docker container:

[20:05:09] INFO: Home Assistant Core finish process exit code 256
[20:05:09] INFO: Home Assistant Core finish process received signal 11
s6-rc: info: service legacy-services: stopping
s6-rc: info: service legacy-services successfully stopped
s6-rc: info: service legacy-cont-init: stopping
s6-rc: info: service legacy-cont-init successfully stopped
s6-rc: info: service fix-attrs: stopping
s6-rc: info: service fix-attrs successfully stopped
s6-rc: info: service s6rc-oneshot-runner: stopping
s6-rc: info: service s6rc-oneshot-runner successfully stopped
s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service legacy-cont-init: starting
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service legacy-services: starting
services-up: info: copying legacy longrun home-assistant (no readiness notification)
s6-rc: info: service legacy-services successfully started

P.S. Let me know if I it's better to create another issue report for this one!

jonferreira commented 4 months ago

Unfortunately, no. I'm still being plagued by this with no response.