Cast Devices Unavailable - 0.78

[edif30]

Home Assistant release with the issue:
0.78

Last working Home Assistant release (if known):
0.77.3

Operating environment (Hass.io/Docker/Windows/etc.):
Docker

Component/platform:
Cast

Description of problem:
Not 100% sure but after #16471, almost all of my cast devices go unavailable in a very short period of time.

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

Traceback (if applicable):
No Traceback. Cast devices just drop off and will not become available until an HA restart.

Additional information:

[cicero200272]

I can confirm that once I manually disconnect/restart a CC device, it will remain unavailable until I restart HA. I did not see any spontaneous dropoffs though.

[michaelarnauts]

Also, a device that was offline when Home Assistant booted will not return.

I'm not using discovery but have configured the IP addresses of my google home devices.

[edif30]

@cicero200272 I think my case was I had some network congestion or something else. But either way, not good that after the timeout period is over that the devices will not re-appear when they are online.

[edif30]

I am running a dev HA container as well as my production container. The dev container is running the latest 0.78. I reverted the changes in the PR #16471 on my production container. Both running side by side. Within a relatively short period of time I have 2 cast devices on my dev container that went unavailable. Production container with reverted changes is running fine.

[awarecan]

Can you try to adjust CONNECTION_RETRY, CONNECTION_RETRY_WAIT, CONNECTION_TIMEOUT value to fit your network environment? Maybe we should make those parameter configurable?

https://github.com/home-assistant/home-assistant/blob/56b0d2e99fb748f25344f11ec21e3163a71729cd/homeassistant/components/media_player/cast.py#L64-L66

[dshokouhi]

I have the same issue too, seems this happened after 0.78

[dshokouhi]

maybe we should just revert the untested change and push out 0.78.1?

[cicero200272]

Can you try to adjust CONNECTION_RETRY, CONNECTION_RETRY_WAIT, CONNECTION_TIMEOUT value to fit your network environment? Maybe we should make those parameter configurable?

If a CC device goes offline (e. g. the cleaning lady accidentally pulled the plug) and I reconnect it some hours later when I get home, the number of retries will most likely be exceeded, no matter how high I set the limit...

Wouldn't it be better to just prevent somehow that the HA startup is blocked and keep the infinite number of retries? Like "skip it for now, try again later"?

[dshokouhi]

@cicero200272 it should honestly work like it did before. Anything turned on at the moment is immediately discovered. Anything else gets discovered when its brought online. The current change is honestly untested according to the PR. The best thing to do here is revert and properly test the change against several users and make sure all edge cases and issues are resolved. Cast is a very large component, this must be breaking for lots and lots of users who just did not notice it yet. I have currently reverted the change in my own environment and devices are able to reconnect just fine. We need to test a wide variety of devices here.

[edif30]

@awarecan adjusting those settings will not cover all use cases. The infinite retry is a back stop for when devices go offline for x period of time due to an accident or long outage duration. I agree with @cicero200272 that it would be better to prevent the HA startup issue than change how the component behaves entirely.

[awarecan]

@dshokouhi old code will block the HA startup if cast is offline according #14956

I think a better way is using current code for startup, after HA start, change the parameter to

CONNECTION_RETRY = None
CONNECTION_RETRY_WAIT = 60
CONNECTION_TIMEOUT = None

PR is welcome

[dshokouhi]

@awarecan thats not true, I have devices offline that reconnect just fine and do not block HA start up. I think we should revert the change and start over and submit once you have a sufficient amount of testers.

[edif30]

@awarecan <=0.77.3 I can unplug all of my cast devices while HA is running, see them go offline, restart HA and HA starts up just fine. I can also stop HA, unplug all cast devices, start HA and HA starts up just fine. #14956 is an edge case.

[awarecan]

Please open PR if you feel that is right. I don't have device to test either way.

[edif30]

@awarecan Wait... I'm confused. You merge a PR that isn't tested that breaks a component to 'possibly' fix an edge case and instead of reverting it knowing that this change broke functionality for other users, you ask for a PR? That doesn't make sense. If you remove infinite retry, a device will NEVER come back online until a restart. That is a functionality flaw. Regardless if it prevents an issue at startup, which is yet to be determined.

[awarecan]

NO, I did not merged it. @balloob did that. I had called out for tester for a while.

[edif30]

Ok I stand corrected, you didn't merge it. In any event, you submitted the PR and it was merged on the basis of 1 test user. And without any verification from the thread indicating an issue at startup. That issue was closed without any response from any affected users. I don't understand how that happens.

[awarecan]

#14956 is auto-closed due #16471 got merged, it is our process. You or other people can always ask for reopen the issue, if the fix did not resolved problem.

In #14956 there are multiple users had reported that they manually applied my fix and it resolved their startup issue.

I feel that it is inappropriate if I keep modify that code since I would not be able to verify the changes, so that I called out for pull request.

[cicero200272]

Guys, calm down... :-)

@awarecan is right, I indeed had the problem that HA froze at least for some minutes when a CC device happened to be offline during HA startup. No idea why you guys did not have issues but I (and obviously some other people) did. So simply reverting the change is not the best option in my opinion...

Probably @OttoWinter or some other expert for the cast component could chime in?

[dshokouhi]

@cicero200272 your issue is far less severe than this issue. At least HA will start up after 5 minutes. Here we have to restart just to regain control. That is a far worse issue than what you were experiencing. In fact I bet if you unplug a device for 5 minutes you will get the same issue. So it is far worse off now than it was before.

[edif30]

Agreed. Slow startup (which is only confirmed for users that posted comments in #14956) vs having to restart each time a cast devices goes offline after the retry timeout to regain control due to this latest change is not comparable. If I had slow startup, I'd take that over losing the ability to control a cast device until a restart in a heartbeat. Thankfully I reverted the change locally but not everyone who experiences this new issue will be able. I would bet the odds as time goes on over the next 24 hours, more users will be reporting this new issue.

[cicero200272]

That is a far worse issue than what you were experiencing.

Agreed. I just wanted to point out that "revert that damn PR and never touch the code again" is also not a good option.

In fact I bet if you unplug a device for 5 minuets you will get the same issue.

No, I already tried that. It just doesn't reconnect, that's all. Still bad enough though...

@awarecan, probably you could raise a new PR for 78.1 to revert #16471 and then try to find a solution that solves all issues?

EDIT: If you need a tester, try me - I run 7 CC devices of different kinds.

[rockstar2020]

All my cast devices are unavailable as well after upgrading to 0.78. I tried to rollback to older releases but still have the same issue.
Is there any manual workaround until a new version is released?
Any comment/hints would be highly appreciated.

[awarecan]

For those users have problem to "re-discover" your chromecast after device offline, could you try to set the logger to debug level

logger:
  default: info
  logs:
    homeassistant.components.media_player.cast: debug

and check whether you have seen those log messages when you bring chromecast back online

"Discovered chromecast with same UUID: %s", discover
"Connecting to cast device %s", cast_info
"Connection successful!"

[edif30]

@mehdiheidari check which cast.py you have. Is it the one from 0.77.3 or 0.78? Chances are you have a cached 0.78 version.

[rockstar2020]

Thanks @edif30!
It's from 0.78.
I managed to get all my casting devices back on by wiping and resorting my hassio instance with a backup I had from 0.78.0b0.
Also I restarted my router to refresh all IP addresses.
I hope the issue doesn't come back again after they go offline.
Thanks for taking time to respond anyway.
Cheers

[adas4190]

Hi. Same here, all devices unavailable and no spoken notification...

[mh-daedalus]

Can confirm same cast issue, I've manually edited my cast.py until a fix with the connection retry limit is found.

[awarecan]

I am going to reopen this issue. For the users still experienced disconnection issue after 0.78.1, please post your cast config and debug log.

In current implementation, the re-connection feature rely on an "internal-discovery" function, which is not depends on the general discovery components. However, this "internal-discovery" function would not be enabled for the scenario

1. user still use deprecated cast platform configuration method
2. user manual set up the host config, see: https://www.home-assistant.io/components/cast/#advanced-use

So, I am not going to fix scenario (1) since it is deprecated (although it may be fixed as side effect of fix scenario 2). I will try to fix scenario (2) by extend "internal-discovery" to support host config.

I hope you can help to provide more information to confirm my findings.

[edif30]

I logged in this morning and only 1 of my devices is unavailable. Where as many would be under 0.78.0. @awarecan I have setup the debug logs and leaving this dev instance running to hopefully capture the event. Any unplugging and waiting for 10-15 min and replugging does not replicate the issue. At least for me.

[phairplay]

I've added the log but won't have anything until the morning

[ArnoutVerbeken]

In current implementation, the re-connection feature reply on an "internal-discovery" function, which is not depends on the general discovery components. However, this "internal-discovery" function would not be enabled for the scenario

1. user still use deprecated cast platform configuration method
2. user manual set up the host config, see: https://www.home-assistant.io/components/cast/#advanced-use

@awarecan What do you mean by the "deprecated cast" platform configuration method?
I use https://www.home-assistant.io/components/cast/, because I don't like the discovery component.

In my yaml I have:

cast:
  media_player:
  - host: 192.168.1.16
  - host: 192.168.1.17
  - host: 192.168.1.18

Is this not correct? How else should we do this?

[awarecan]

@ArnoutVerbeken You are good.

[edif30]

@awarecan I have an event where a cast device drops off and it still shows as unavailable when it is online. I will send you a message on Discord so you can see the logs.

[phairplay]

here is the log unavailable from 2.45am

2018-09-22 02:45:28 WARNING (Thread-5) [pychromecast.socket_client] Heartbeat timeout, resetting connection
2018-09-22 02:45:28 DEBUG (Thread-5) [pychromecast.socket_client] connection listener: 72468c90 (CastStatusListener)
2018-09-22 02:45:28 DEBUG (Thread-5) [homeassistant.components.media_player.cast] Received cast device connection status: LOST
2018-09-22 02:45:28 DEBUG (Thread-5) [homeassistant.components.media_player.cast] Cast device availability changed: LOST
2018-09-22 02:45:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=media_player.bedroom_speaker, old_state=<state media_player.bedroom_speaker=off; friendly_name=Bedroom Speaker, supported_features=21437 @ 2018-09-21T10:16:24.628534+01:00>, new_state=<state media_player.bedroom_speaker=unavailable; friendly_name=Bedroom Speaker, supported_features=21437 @ 2018-09-22T02:45:28.119801+01:00>>
2018-09-22 02:45:28 DEBUG (Thread-5) [pychromecast.socket_client] connection listener: 72468c90 (CastStatusListener)
2018-09-22 02:45:28 DEBUG (Thread-5) [homeassistant.components.media_player.cast] Received cast device connection status: CONNECTING
2018-09-22 02:45:30 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=below_horizon; next_dawn=2018-09-22T05:16:31+00:00, next_dusk=2018-09-22T18:40:47+00:00, next_midnight=2018-09-22T23:58:09+00:00, next_noon=2018-09-22T11:58:39+00:00, next_rising=2018-09-22T05:50:55+00:00, next_setting=2018-09-22T18:06:23+00:00, elevation=-32.36, azimuth=31.85, friendly_name=Sun @ 2018-09-21T19:08:49.077989+01:00>, new_state=<state sun.sun=below_horizon; next_dawn=2018-09-22T05:16:31+00:00, next_dusk=2018-09-22T18:40:47+00:00, next_midnight=2018-09-22T23:58:09+00:00, next_noon=2018-09-22T11:58:39+00:00, next_rising=2018-09-22T05:50:55+00:00, next_setting=2018-09-22T18:06:23+00:00, elevation=-32.28, azimuth=32.13, friendly_name=Sun @ 2018-09-21T19:08:49.077989+01:00>>
2018-09-22 02:45:32 INFO (MainThread) [homeassistant.components.media_player.kodi] Unable to connect to Kodi via websocket
2018-09-22 02:45:35 DEBUG (Thread-5) [pychromecast.socket_client] connection listener: 72468c90 (CastStatusListener)
2018-09-22 02:45:35 DEBUG (Thread-5) [homeassistant.components.media_player.cast] Received cast device connection status: FAILED
2018-09-22 02:45:35 ERROR (Thread-5) [pychromecast.socket_client] Failed to connect, retrying in 2.0s
2018-09-22 02:45:35 INFO (SyncWorker_7) [homeassistant.components.device_tracker.nmap_tracker] No MAC address found for 192.168.1.17
2018-09-22 02:45:35 INFO (SyncWorker_7) [homeassistant.components.device_tracker.nmap_tracker] nmap scan successful
2018-09-22 02:45:37 DEBUG (Thread-5) [pychromecast.socket_client] connection listener: 72468c90 (CastStatusListener)
2018-09-22 02:45:37 DEBUG (Thread-5) [homeassistant.components.media_player.cast] Received cast device connection status: CONNECTING
2018-09-22 02:45:37 DEBUG (Thread-5) [pychromecast.socket_client] connection listener: 72468c90 (CastStatusListener)
2018-09-22 02:45:37 DEBUG (Thread-5) [homeassistant.components.media_player.cast] Received cast device connection status: FAILED
2018-09-22 02:45:37 DEBUG (Thread-5) [pychromecast.socket_client] Failed to connect, retrying in 2.0s
2018-09-22 02:45:39 DEBUG (Thread-5) [pychromecast.socket_client] connection listener: 72468c90 (CastStatusListener)
2018-09-22 02:45:39 DEBUG (Thread-5) [homeassistant.components.media_player.cast] Received cast device connection status: CONNECTING
2018-09-22 02:45:39 DEBUG (Thread-5) [pychromecast.socket_client] connection listener: 72468c90 (CastStatusListener)
2018-09-22 02:45:39 DEBUG (Thread-5) [homeassistant.components.media_player.cast] Received cast device connection status: FAILED
2018-09-22 02:45:39 ERROR (Thread-5) [pychromecast.socket_client] Failed to connect. No retries.
2018-09-22 02:45:39 DEBUG (Thread-5) [pychromecast.socket_client] connection listener: 72468c90 (CastStatusListener)
2018-09-22 02:45:39 DEBUG (Thread-5) [homeassistant.components.media_player.cast] Received cast device connection status: DISCONNECTED

[awarecan]

What is your cast config? Did you get any zeroconf-ServiceBrowser__googlecast._tcp.local. in your log?

[phairplay]

Added manually the ip addresses to the cast in the config file.
Sorry didn't see any I've rebooted now I'll look again tomorrow

[awarecan]

Current implementation has problem with manual configured host IP.

[phairplay]

I can confirm all is working again removed cast and allows auto discovery and installed .78.3

Cheers guys

[nelbs]

I updated to 0.78.3 (Hasbian) but after a while both my chromecasts become and stays unavailable. However these devices are still connected to the network and work fine. After a day I got the following errors. Could this error be related to this issue? I know it's fixed in 0.78.3 but I did not have this error till 0.78.

I am using discovery to add the CC.

2018-09-27 02:13:06 WARNING (Thread-29) [pychromecast.socket_client] Heartbeat timeout, resetting connection
2018-09-27 02:13:07 ERROR (Thread-29) [pychromecast.socket_client] Failed to connect, retrying in 2.0s
2018-09-27 02:13:13 ERROR (Thread-29) [pychromecast.socket_client] Failed to connect. No retries.
2018-09-27 02:16:39 WARNING (Thread-28) [pychromecast.socket_client] Heartbeat timeout, resetting connection
2018-09-27 02:16:46 ERROR (Thread-28) [pychromecast.socket_client] Failed to connect, retrying in 2.0s
2018-09-27 02:16:50 ERROR (Thread-28) [pychromecast.socket_client] Failed to connect. No retries.

[JaapBraam]

I am using 0.79.3 with debug enabled.

My logging from startup to unavailable:

2018-10-11 20:07:43 INFO (MainThread) [homeassistant.loader] Loaded cast from homeassistant.components.cast
2018-10-11 20:07:43 INFO (MainThread) [homeassistant.setup] Setting up cast
2018-10-11 20:07:43 INFO (MainThread) [homeassistant.setup] Setup of domain cast took 0.0 seconds.
2018-10-11 20:07:45 INFO (MainThread) [homeassistant.loader] Loaded media_player.cast from homeassistant.components.media_player.cast
2018-10-11 20:07:45 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.cast
2018-10-11 20:07:47 DEBUG (Thread-14) [homeassistant.components.media_player.cast] Starting internal pychromecast discovery.
2018-10-11 20:07:47 DEBUG (zeroconf-ServiceBrowser__googlecast._tcp.local.) [homeassistant.components.media_player.cast] Discovered chromecast ChromecastInfo(host='192.168.1.114', port=8009, uuid='e713a046-7407-312b-c538-3f87d5a780ca', manufacturer='Google Inc.', model_name='Chromecast Audio', friendly_name='Tuinkamer')
2018-10-11 20:07:48 DEBUG (zeroconf-ServiceBrowser__googlecast._tcp.local.) [homeassistant.components.media_player.cast] Discovered chromecast ChromecastInfo(host='192.168.1.118', port=8009, uuid='3a1ca1f0-43b4-379a-5844-af0bf3bf862d', manufacturer='Harman Kardon', model_name='JBL Playlist', friendly_name='Eetkamer')
2018-10-11 20:07:48 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connecting to cast device ChromecastInfo(host='192.168.1.114', port=8009, uuid='e713a046-7407-312b-c538-3f87d5a780ca', manufacturer='Google Inc.', model_name='Chromecast Audio', friendly_name='Tuinkamer')
2018-10-11 20:07:48 INFO (Thread-4) [pychromecast] Querying device status
2018-10-11 20:07:48 DEBUG (zeroconf-ServiceBrowser__googlecast._tcp.local.) [homeassistant.components.media_player.cast] Discovered chromecast ChromecastInfo(host='192.168.1.143', port=8009, uuid='05babb85-15e5-be2e-f7b8-a90e53c13e05', manufacturer='PHILIPS', model_name='QM163E', friendly_name='43PUS6501/12')
2018-10-11 20:07:48 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connecting to cast device ChromecastInfo(host='192.168.1.118', port=8009, uuid='3a1ca1f0-43b4-379a-5844-af0bf3bf862d', manufacturer='Harman Kardon', model_name='JBL Playlist', friendly_name='Eetkamer')
2018-10-11 20:07:48 INFO (Thread-8) [pychromecast] Querying device status
2018-10-11 20:07:48 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connecting to cast device ChromecastInfo(host='192.168.1.143', port=8009, uuid='05babb85-15e5-be2e-f7b8-a90e53c13e05', manufacturer='PHILIPS', model_name='QM163E', friendly_name='43PUS6501/12')
2018-10-11 20:07:48 INFO (Thread-15) [pychromecast] Querying device status
2018-10-11 20:07:48 DEBUG (zeroconf-ServiceBrowser__googlecast._tcp.local.) [homeassistant.components.media_player.cast] Discovered chromecast ChromecastInfo(host='192.168.1.148', port=8009, uuid='5a5d9912-d4a3-0749-d3dc-d07e39be2d39', manufacturer='Google Inc.', model_name='Chromecast Audio', friendly_name='Woonkamer')
2018-10-11 20:07:48 DEBUG (zeroconf-ServiceBrowser__googlecast._tcp.local.) [homeassistant.components.media_player.cast] Discovered chromecast ChromecastInfo(host='192.168.1.148', port=42791, uuid='28adbae8-d2f5-4a52-a5e5-200d7b67bae3', manufacturer='', model_name='Google Cast Group', friendly_name='Thuisgroep')
2018-10-11 20:07:48 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connecting to cast device ChromecastInfo(host='192.168.1.148', port=8009, uuid='5a5d9912-d4a3-0749-d3dc-d07e39be2d39', manufacturer='Google Inc.', model_name='Chromecast Audio', friendly_name='Woonkamer')
2018-10-11 20:07:48 INFO (Thread-2) [pychromecast] Querying device status
2018-10-11 20:07:48 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connecting to cast device ChromecastInfo(host='192.168.1.148', port=42791, uuid='28adbae8-d2f5-4a52-a5e5-200d7b67bae3', manufacturer='', model_name='Google Cast Group', friendly_name='Thuisgroep')
2018-10-11 20:07:48 INFO (Thread-16) [pychromecast] Querying device status
2018-10-11 20:07:48 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connection successful!
2018-10-11 20:07:48 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connection successful!
2018-10-11 20:07:48 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connection successful!
2018-10-11 20:07:48 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connection successful!
2018-10-11 20:07:48 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connection successful!
2018-10-11 21:09:12 DEBUG (zeroconf-ServiceBrowser__googlecast._tcp.local.) [homeassistant.components.media_player.cast] Discovered chromecast ChromecastInfo(host='192.168.1.114', port=42791, uuid='28adbae8-d2f5-4a52-a5e5-200d7b67bae3', manufacturer='', model_name='Google Cast Group', friendly_name='Thuisgroep')
2018-10-11 21:09:12 DEBUG (MainThread) [homeassistant.components.media_player.cast] Discovered chromecast with same UUID: ChromecastInfo(host='192.168.1.114', port=42791, uuid='28adbae8-d2f5-4a52-a5e5-200d7b67bae3', manufacturer='', model_name='Google Cast Group', friendly_name='Thuisgroep')
2018-10-11 21:09:12 DEBUG (MainThread) [homeassistant.components.media_player.cast] Disconnecting from chromecast socket.
2018-10-11 21:09:13 INFO (Thread-27) [pychromecast.socket_client] Stopped while reading message, disconnecting.
2018-10-11 21:09:13 DEBUG (Thread-27) [homeassistant.components.media_player.cast] Received cast device connection status: DISCONNECTED
2018-10-11 21:09:13 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connecting to cast device ChromecastInfo(host='192.168.1.114', port=42791, uuid='28adbae8-d2f5-4a52-a5e5-200d7b67bae3', manufacturer='', model_name='Google Cast Group', friendly_name='Thuisgroep')
2018-10-11 21:09:13 INFO (Thread-12) [pychromecast] Querying device status
2018-10-11 21:09:13 ERROR (Thread-12) [pychromecast.socket_client] Failed to connect, retrying in 5.0s

The last line containing 'cast' is from 2 hours ago. It says retrying in 5.0s but it doesn't...

[pergolafabio]

i too have the issue , that aftter about 12 hours or something , my chromecast is in the state unavailable
i need to restart HA in order to get it work, running 80.1 version here , with hassos 1.11
i think i only have the issue with the chromecast, my google home mini is stabble

are there still logs needed? can i help ?

[nelbs]

I'm planning to open a new issues as advised by @awarecan in #16924

I turned on debug logger and waiting till the error will occur.

[heymoe]

I know this is closed but I'm running 81.X (.6 currently) on a RP3B with HassOS 1.12 and currently when I restart HA things hang and don't seem to get past this. Sometimes I can stop and start the HA docker image and it will start OK or I have to edit my config to manually define a singe cast device which prevents HA from doing auto discovery using the cast integration to get it to boot.

2018-11-05 19:28:46 INFO (SyncWorker_16) [pychromecast] Querying device status
2018-11-05 19:28:46 INFO (SyncWorker_2) [pychromecast] Querying device status
2018-11-05 19:28:46 ERROR (SyncWorker_16) [pychromecast.socket_client] Failed to connect, retrying in 5.0s                                                           
2018-11-05 19:28:46 ERROR (SyncWorker_2) [pychromecast.socket_client] Failed to connect, retrying in 5.0s