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

Chromecast causing startup issues #14956

Closed
point-4ward opened this issue Jun 13, 2018 · 34 comments · Fixed by #16471
Closed

Chromecast causing startup issues #14956

point-4ward opened this issue Jun 13, 2018 · 34 comments · Fixed by #16471
Assignees

Comments

@point-4ward
Copy link
Contributor

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

@point-4ward
Copy link
Contributor Author

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.

@point-4ward
Copy link
Contributor Author

Ugh, why is the close&comment button so close to the comment one 🙄 🤣

@deadman96385
Copy link

deadman96385 commented Jun 13, 2018

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

@point-4ward
Copy link
Contributor Author

point-4ward commented Jun 14, 2018

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
Copy link
Contributor

Mariusthvdb commented Jun 14, 2018

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...

@point-4ward
Copy link
Contributor Author

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
Copy link
Contributor

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

@point-4ward
Copy link
Contributor Author

@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
Copy link
Contributor

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
Copy link

rfpludwick commented Jun 26, 2018

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
Copy link

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

@aronsky
Copy link
Contributor

aronsky commented Jul 31, 2018

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
Copy link

webxl commented Aug 2, 2018

@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
Copy link

jstys commented Aug 6, 2018

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
Copy link

nikiyao commented Aug 31, 2018

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
Copy link

tomuta commented Sep 7, 2018

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
Copy link
Contributor

awarecan commented Sep 7, 2018

No, #16261 did nothing about it.

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

@araa47
Copy link

araa47 commented Nov 12, 2018

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
Copy link

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

@tomuta
Copy link

tomuta commented Nov 27, 2018

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
Copy link
Contributor

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

@jlbphotos
Copy link

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
Copy link

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

@nelbs
Copy link

nelbs commented Dec 7, 2018

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
Copy link

tomuta commented Jan 19, 2019

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
Copy link

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
Copy link

tomuta commented Jan 21, 2019

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
Copy link

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

@poldim
Copy link

poldim commented Feb 1, 2019

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
Copy link

tomuta commented Feb 1, 2019

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
Copy link

poldim commented Feb 2, 2019 via email

@HerrMuellerluedenscheid
Copy link

HerrMuellerluedenscheid commented Feb 2, 2019

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
Copy link

tomuta commented Feb 6, 2019

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.

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 a pull request may close this issue.