Core: Chromecast causing startup issues

[mf-social]

Home Assistant release with the issue: 71.0

Last working Home Assistant release (if known): 71.b0

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

Component/platform: chromecast

Description of problem:

Homeassistant freezes completely on startup when chromecast can't connect

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

media_player:
  - platform: cast

Traceback (if applicable):

Jun 13 17:11:20 node-zero hass[2148]: 2018-06-13 17:11:20 ERROR (SyncWorker_2) [pychromecast.socket_client] Failed to connect, retrying in 5.0s

Additional information:
The error message isn't new, I was getting it quite regularly before anyway, but it's never actually stopped the startup process before this upgrade. Now restarts can take anything from the 20-30 seconds they normally take (presumably where it doesn't fail to connect), to nearly 5 minutes because it just seems to sit on that error and wait.

That is to say, prior to this upgrade I'm sure it was regularly getting fail to connect errors during startup, but it would still give me a frontend in the normal time. For some reason since this update it is now running through the startup process, getting to that error message and then nothing happens for ages, and then suddenly the flurry of activity starts again and we're back in business.

Not sure why, I can't see any mention of chromecast in the changes this version (but I'll be honest I haven't been paying as much attention these last few weeks)

Expected behaviour
Startup continues regardless of chromecast failing to connect.

@OttoWinter

[mf-social]

Further example, note the times...

Jun 13 17:27:10 node-zero hass[2566]: 2018-06-13 17:27:10 ERROR (SyncWorker_2) [pychromecast.socket_client] Failed to connect, retrying in 5.0s
Jun 13 17:28:52 node-zero hass[2566]: 2018-06-13 17:28:52 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=media_player.
Jun 13 17:28:52 node-zero hass[2566]: 2018-06-13 17:28:52 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 146.62s
Jun 13 17:28:52 node-zero hass[2566]: 2018-06-13 17:28:52 INFO (MainThread) [homeassistant.core] Starting Home Assistant core loop

Just completely froze from 17:27:10 - 17:28:52 . I'm certain it never used to do this.

During that time I switched a few lights on and off and the changes haven't registered.

[mf-social]

Ugh, why is the close&comment button so close to the comment one :roll_eyes: :rofl:

[deadman96385]

I am having the same issues with my cast devices, they are holding up startup for a long time.

[mf-social]

Another 4-and-a-half minutes this morning...

Jun 14 13:03:56 node-zero hass[10808]: 2018-06-14 13:03:56 ERROR (SyncWorker_0) [pychromecast.socket_client] Failed to connect, retrying in 5.0s
Jun 14 13:08:33 node-zero hass[10808]: 2018-06-14 13:08:33 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=media_player.bedroom, old_state=<state media_player.bedroom=unavailable; friendly_name=Bedroom, supported_features=21437, icon=mdi:play @ 2018-06-14T13:03:26.428685+01:00>, new_state=<state media_player.bedroom=off; friendly_name=Bedroom, supported_features=21437, icon=mdi:play @ 2018-06-14T13:08:33.628777+01:00>>

[Mariusthvdb]

pleas let me ask, since i too have longer setup times than desired, and a few chrome casts (audio and video): are they powered on when you're starting up?
In my case they're off most of the time, but maybe even so the media_player: platform: cast can be of trouble? Media_player setup times far over 150 secs here, maybe even longer, not sure tbh. Just never gave it a thought it could have been the Casts being the troublemakers since they're off...

[mf-social]

Yeah, they're all on. Like I said the error isn't new, and I still get it occasionally throughout the day, but it's never frozen the startup process before.

[awarecan]

Hi,

I don't have Cast and never look at this component, I just happen to see your issue when I am looking for my Roku player issue. Anyway, I think problem is coming from this code block:
https://github.com/home-assistant/home-assistant/blob/2839f0ff5fec87a7c636a9713d6c340f351e86c1/homeassistant/components/media_player/cast.py#L359-L374

Actually, _get_chromecast_from_host method accept tries, retry_wait, timeout and blocking parameters. But above code doesn't provided any one of them. According pychromcast's docstring, timeout default is 30s, and tries default is inifinite. So maybe you guys can try on this patch, play with the numbers, find optimized parameters for retry logic :

--- a/homeassistant/components/media_player/cast.py
+++ b/homeassistant/components/media_player/cast.py
@@ -361,7 +361,8 @@ class CastDevice(MediaPlayerDevice):
         # pylint: disable=protected-access
         _LOGGER.debug("Connecting to cast device %s", cast_info)
         chromecast = await self.hass.async_add_job(
-            pychromecast._get_chromecast_from_host, attr.astuple(cast_info))
+            pychromecast._get_chromecast_from_host, attr.astuple(cast_info),
+            3, 2, 10)
         self._chromecast = chromecast
         self._status_listener = CastStatusListener(self, chromecast)
         # Initialise connection status as connected because we can only

[mf-social]

@awarecan - thanks for the suggestion, but I think this may have been fixed (maybe on purpose, or maybe by accident 😝 ) with the move to a standalone cast: component in the betas.

I'm going to leave this open for a short while just to make sure though, unless anyone can specifically confirm that this isn't a fluke.

[awarecan]

The code I referenced is on dev branch, the new implement must move it into an async wrapper, so that it won't block the setup process.

[rfpludwick]

This is what I'm getting. Upgraded to .72.1, and I've even tried disabling cast outright. It hangs my startup, rendering HA entirely inoperable.

tail -f home-assistant.log
2018-06-26 07:29:54 WARNING (Recorder) [homeassistant.components.recorder] Ended unfinished session (id=28 from 2018-06-26 14:22:21.479830)
2018-06-26 07:32:45 ERROR (Thread-7) [pychromecast.socket_client] Failed to connect, retrying in 5.0s

[rfpludwick]

For what it's worth, I manually made the change that @awarecan listed above, and it fixed my problem. Thanks for that.

[aronsky]

I only figured out the problem is with the chromecast component after spending hours on the issue (my Home Assistant issue was not bringing up the web UI at all), and even reinstalling Hassbian from scratch (the issue started after a power outage, and I thought maybe something was wrong because of that - apparently, I simply never had the Chromecasts on when restarting Home Assitant before...

[webxl]

@awarecan What is needed to move it into an async wrapper? It seems to already be async, at least according to what's listed here: https://developers.home-assistant.io/docs/en/asyncio_working_with_async.html

[jstys]

Noticing the same issue where it seems like Chromecasts are blocking startup on 0.75.1. This also occurred on power outage for me as well.

[nikiyao]

Experiencing the same thing, sometimes it can take quite a while for it to kick over and start. I had previously been restoring after doing this. It's happened again and I'm trying to wait it out.

[tomuta]

Still a problem with 0.77.3. Just ran into this and wasted more than an hour trying to figure out why HA just hangs after a restart. Turned out i had a chromecast device that wasn't powered on anymore. Luckily, the manual modifications by @awarecan got it working again.

Looks like #16261 fixed it, though.

[awarecan]

No, #16261 did nothing about it.

I opened a PR #16471, but need people to verify it.

[araa47]

2018-11-12 21:26:07 INFO (MainThread) [homeassistant.setup] Setup of domain media_player took 0.8 seconds.
2018-11-12 21:26:07 INFO (MainThread) [homeassistant.loader] Loaded media_player.cast from homeassistant.components.media_player.cast
2018-11-12 21:26:07 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.cast
2018-11-12 21:26:07 INFO (MainThread) [homeassistant.setup] Setup of domain light took 0.9 seconds.
2018-11-12 21:26:07 INFO (MainThread) [homeassistant.loader] Loaded light.lifx from homeassistant.components.light.lifx
2018-11-12 21:26:07 INFO (MainThread) [homeassistant.components.light] Setting up light.lifx
2018-11-12 21:26:07 INFO (Thread-6) [pychromecast] Querying device status
2018-11-12 21:26:08 INFO (Thread-15) [pychromecast] Querying device status
2018-11-12 21:26:08 INFO (Thread-14) [pychromecast] Querying device status
2018-11-12 21:26:08 INFO (MainThread) [homeassistant.setup] Setup of domain sensor took 2.8 seconds.
2018-11-12 21:26:08 ERROR (Thread-14) [pychromecast.socket_client] Failed to connect, retrying in 5.0s

home-assistant-frontend==20181103.3
homeassistant==0.82.0

HASS wont boot and gets stuck over here, can't seem to get hass to boot up at all. Currently running hass based off these instructions https://www.home-assistant.io/docs/installation/raspberry-pi/ on a pi3+.

[perozonp]

homeassistant==0.82.1
same problem
solved using @awarecan method (thanks!)
hope a permanent solution will be available soon.

[tomuta]

homeassistant==0.82.1
same problem
solved using @awarecan method (thanks!)
hope a permanent solution will be available soon.

So sounds like the fix never actually made it in or regressed, and the issue should probably re-opened?

[KarimGeiger]

Can confirm that this is still an issue, at least for me. That fix solved it, but I had to apply it manually.

[jlbphotos]

Still an issue for me 0.82 Hassio / Ubunti Docker.io and Intel NUC
my chromecast couldnt access internet but still on network stopped HA from starting GUI.
Just today a google home mini did the same thing after a power out and blocked from starting.

[ptersilie]

Same problem for me but with the Sonos component. Startup just hangs forever at [homeassistant.components.media_player] Setting up media_player.sonos.

[nelbs]

I'm facing the same issue frequently. Restarting homeassistant via the frontend or SSH doesnt work. The homeassistant process is running but I cant reach the frontend. It seems that the startup process stucks on the following message:

Dec 07 23:44:23 hassbian hass[11068]: 2018-12-07 23:44:23 INFO (Thread-4) [pychromecast] Querying device status

The only thing that worked is to reboot my Pi.

homeassistant==0.82.1
same problem
solved using @awarecan method (thanks!)
hope a permanent solution will be available soon.

@perozonp Which method are you refering to?

[HerrMuellerluedenscheid]

I had the same problem and I think I traced it down (for some scenarios on light weight systems like the raspberry pi zero which I'm working on at the moment). It was a little tricky as there are many exceptions being caught in pychromecast without raising or logging them! So let me recite the zen of python, index 10, where it says:

Errors should never pass silently.

I checked the entropy of ssl using ssl.RAND_status and it turned out that ssl did not gather enough randomness when pychromecast was firing up right after boot from a system daemon. I also tried adding randomness using ssl.RAND_add but had no luck with that either, even though this seemed like a reasonable way to go. Instead I found that installing rng-tools which feeds the random number generator solved the issue for me (as suggested here).

Maybe this helps others.

[tomuta]

I had the same problem and I think I traced it down (for some scenarios on light weight systems like the raspberry pi zero which I'm working on at the moment). It was a little tricky as there are many exceptions being caught in pychromecast without raising or logging them! So let me recite the zen of python, index 10, where it says:

Errors should never pass silently.

I checked the entropy of ssl using ssl.RAND_status and it turned out that ssl did not gather enough randomness when pychromecast was firing up right after boot from a system daemon. I also tried adding randomness using ssl.RAND_add but had no luck with that either, even though this seemed like a reasonable way to go. Instead I found that installing rng-tools which feeds the random number generator solved the issue for me (as suggested here).

Maybe this helps others.

You may be onto something. I was having issues with zwave that would stop working almost daily for no apparent reason. I do have several chromecast devices, and I've had random issues with them in regards to HA. Anyway, I installed the rng-tools package shortly after reading your reply, and the system has been performing flawlessly since. Granted it's only been 2 days, but time will tell. I'll leave it in this state for a few more days.

[kwakkel1000]

I have 2 Speaker groups with chromecasts. these devices seem to be the problem (it can never connect because they ain't a device).
But the fix to not retry forever is still not in the current code. so had to fix it myself.

[tomuta]

I have 2 Speaker groups with chromecasts. these devices seem to be the problem (it can never connect because they ain't a device).
But the fix to not retry forever is still not in the current code. so had to fix it myself.

Are you referring to @awarecan's modification?

https://github.com/home-assistant/home-assistant/blob/4b3cdb9f4e191e4892a613048db48a0c05369e7b/homeassistant/components/media_player/cast.py#L380-L384

I agree, it doesn't look like this ever made it in.

[kwakkel1000]

Yes that modification is exactly the one i need now.
I just updated home assistant and had to refix the code.

[poldim]

On version 0.86.3 and getting these errors. I have no mediaplayers manually configured.

2019-01-26 10:24:24 ERROR (Thread-404) [pychromecast.socket_client] Failed to connect: timed out. aborting due to stop signal.
2019-01-26 10:24:26 ERROR (Thread-202) [pychromecast.socket_client] Failed to connect, retrying in 5.0s
2019-01-26 10:24:29 ERROR (Thread-402) [pychromecast.socket_client] Failed to connect: timed out. aborting due to stop signal.
2019-01-26 10:24:49 ERROR (Thread-8) [pychromecast.socket_client] Failed to connect: timed out. aborting due to stop signal. /usr/src/app/homeassistant/helpers/aiohttp_client.py:161: RuntimeWarning: coroutine 'noop2' was never awaited connector.close()
2019-01-26 10:25:21 ERROR (Thread-202) [pychromecast.socket_client] Failed to connect, retrying in 5.0s
2019-01-26 10:26:39 ERROR (Thread-202) [pychromecast.socket_client] Failed to connect, retrying in 5.0s
2019-01-26 10:27:47 ERROR (Thread-202) [pychromecast.socket_client] Failed to connect, retrying in 5.0s
2019-01-26 10:28:55 ERROR (Thread-202) [pychromecast.socket_client] Failed to connect, retrying in 5.0s
2019-01-26 10:35:44 ERROR (Thread-202) [pychromecast.socket_client] Failed to connect, retrying in 5.0s
2019-01-26 10:37:50 ERROR (Thread-202) [pychromecast.socket_client] Failed to connect, retrying in 5.0s
2019-01-26 10:38:45 ERROR (Thread-202) [pychromecast.socket_client] Failed to connect, retrying in 5.0s
2019-01-26 10:39:50 ERROR (Thread-202) [pychromecast.socket_client] Failed to connect, retrying in 5.0s

[tomuta]

I haven't had any issues whatsoever for the past 2 weeks. Only thing I did was install the rng-tools package. That solved all kinds of weird issues for me, like zwave devices not working anymore. Thanks @HerrMuellerluedenscheid! Haven't tested the chromecast-powered-off-at-hass-startup case, though.

[poldim]

I'm using the latest docker so I can't really install things in it

On Fri, Feb 1, 2019 at 12:44 PM Tom [e-mail] wrote:

I haven't had any issues whatsoever for the past 2 weeks. Only thing I did
was install the rng-tools package. That solved all kinds of weird issues
for me, like zwave devices not working anymore. Thanks
@HerrMuellerluedenscheid https://github.com/HerrMuellerluedenscheid!
Haven't tested the chromecast-powered-off-at-hass-startup case, though.

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
https://github.com/home-assistant/home-assistant/issues/14956#issuecomment-459861541,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AQFpUbmHAEE91gi3Cbiydh3XIYbO8q-dks5vJKcugaJpZM4UmhWg
.

[HerrMuellerluedenscheid]

I'm using the latest docker so I can't really install things in it
…
On Fri, Feb 1, 2019 at 12:44 PM Tom @.*> wrote: I haven't had any issues whatsoever for the past 2 weeks. Only thing I did was install the rng-tools package. That solved all kinds of weird issues for me, like zwave devices not working anymore. Thanks @HerrMuellerluedenscheid https://github.com/HerrMuellerluedenscheid! Haven't tested the chromecast-powered-off-at-hass-startup case, though. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#14956 (comment)>, or mute the thread https://github.com/notifications/unsubscribe-auth/AQFpUbmHAEE91gi3Cbiydh3XIYbO8q-dks5vJKcugaJpZM4UmhWg .

I'm not using docker or home assistant so I'm not really feeling devoted to do that myself but I think it would be reasonable to ask the maintainers of the HA docker containers to simply include rng-tools in each container.

[tomuta]

I just ran into my zwave issues again. Installing the rng-tools package helped greatly, but isn't a 100% fix unfortunately. I haven't manually patched the code as per @awarecan's post.