Core: 0.113.beta - Chromecasts lost overnight

[DubhAd]

The problem

With 0.113.b1 (and b0) Chromecast devices go unavailable overnight, as reported by others in Discord.

Environment

• Home Assistant Core release with the issue: 0.113.b0
• Last working Home Assistant Core release (if known): 0.112.5
• Operating environment (OS/Container/Supervised/Core): Core
• Integration causing this issue: cast
• Link to integration documentation on our website: https://www.home-assistant.io/integrations/cast

Problem-relevant configuration.yaml

N/A

Traceback/Error logs

2020-07-18 02:29:54 WARNING (Thread-35) [pychromecast.socket_client] [Master Bedroom Speaker(172.23.72.80):8009] Heartbeat timeout, resetting connection
2020-07-18 02:29:54 INFO (Thread-35) [pychromecast.controllers] Receiver:channel_disconnected

Additional information

[frenck]

I've been able to reproduce it on demand by:

• Go to the Google Home app on your mobile device
• Select/click on the device you want to simulate this on
• Select the cog icon in the top for settings
• Click on the ... menu in the top
• Click on "Reboot device"

After that the device becomes unavailable and won't restore.

In the logs I've found this:

Unfortunately, not more.

[probot-home-assistant[bot]]

cast documentation
cast source
_{^{(message by IssueLinks)}}

[Tediore]

I also see this warning in the logs from homeassistant.components.cast.discovery, one for each speaker:

setup_internal_discovery failed to get info for 0e9f2c3d-2a23-e9f1-8418-7f9429cc20ca, Google-Home-0e9f2c3d2a23e9f184187f9429cc20ca-1._googlecast._tcp.local.

FWIW I've seen the "heartbeat timeout" warning in previous versions during this nightly reboot with no issues with the speaker reconnecting afterward.

[firstof9]

2020-07-18 05:09:21 WARNING (Thread-101) [pychromecast.socket_client] [Kitchen display(192.168.1.25):8009] Heartbeat timeout, resetting connection
2020-07-18 05:09:36 ERROR (Thread-101) [pychromecast.socket_client] [Kitchen display(192.168.1.25):8009] Failed to connect to service Lenovo-Smart-Display-206e2e1ac77a4f315ca346f5a57d59f4._googlecast._tcp.local., retrying in 5.0s

Then when I restart Home Assistant the following populates in the log:

2020-07-18 09:22:52 ERROR (Thread-102) [pychromecast.socket_client] [Living room Home(192.168.1.21):8009] Failed to connect. No retries.
2020-07-18 09:22:52 ERROR (Thread-102) [pychromecast.socket_client] [Living room Home(192.168.1.21):8009] _cleanup
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/pychromecast/socket_client.py", line 736, in _cleanup
    self.socket.close()
AttributeError: 'NoneType' object has no attribute 'close'
2020-07-18 09:22:52 ERROR (Thread-103) [pychromecast.socket_client] [Girls Room speaker(192.168.1.40):8009] Failed to connect. No retries.
2020-07-18 09:22:52 ERROR (Thread-103) [pychromecast.socket_client] [Girls Room speaker(192.168.1.40):8009] _cleanup
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/pychromecast/socket_client.py", line 736, in _cleanup
    self.socket.close()
AttributeError: 'NoneType' object has no attribute 'close'
2020-07-18 09:22:54 ERROR (Thread-99) [pychromecast.socket_client] [Master bedroom Home(192.168.1.19):8009] Failed to connect. No retries.
2020-07-18 09:22:54 ERROR (Thread-99) [pychromecast.socket_client] [Master bedroom Home(192.168.1.19):8009] _cleanup
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/pychromecast/socket_client.py", line 736, in _cleanup
    self.socket.close()
AttributeError: 'NoneType' object has no attribute 'close'
2020-07-18 09:22:54 ERROR (Thread-105) [pychromecast.socket_client] [Girls Room TV(192.168.1.11):8009] Failed to connect. No retries.
2020-07-18 09:22:54 ERROR (Thread-105) [pychromecast.socket_client] [Girls Room TV(192.168.1.11):8009] _cleanup
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/pychromecast/socket_client.py", line 736, in _cleanup
    self.socket.close()
AttributeError: 'NoneType' object has no attribute 'close'
Home Assistant attempting to restart.

[emontnemery]

I unfortunately can't reproduce the problem.

For those who see the issue, please help by:

• Confirming if the Chromecasts are automatically added or manually whitelisted by IP or UUID
• Enable extra logging and reproduce:

logger:
  default: info
  logs:
    homeassistant.components.cast: debug
    homeassistant.components.cast.media_player: debug
    pychromecast: debug
    pychromecast.discovery: debug
    pychromecast.socket_client: debug
    homeassistant.components.zeroconf: debug
    zeroconf: info

@frenck is it 100% reproducible for you when you reboot the chromecast?

Edit: I can reproduce it now.

[frenck]

Yes, for me it is 100% reproducible on any mini or hub device with that method. I will run a full trace

[emontnemery]

Thanks! No need for the trace, it's a bug with pychromecast being too zealous cleaning up when a cast disappears from the network.

[emontnemery]

@frenck Can you help to verify this change in pychromecast/discovery.py solves the problem:

                 if len(services_for_uuid[0]) == 0:
-                    self.services.pop(uuid)
                     service_removed = True

[frenck]

Will test it right away...

[frenck]

Confirmed, patched that manually inside my production container. After that, I'm not able to reproduce it anymore. Removed it again, and the reproduction breaks it again.

👍