Core: pychromecast.error.NotConnected: Chromecast x.x.x.x:yyyy is connecting...

[marc-gist]

Home Assistant release with the issue:

many, currently i'm on 0.98.4

Last working Home Assistant release (if known):
None

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

Component/platform:

https://www.home-assistant.io/components/cast/

Description of problem:

Constantly getting:
pychromecast.error.NotConnected: Chromecast x.x.x.x:8009 is connecting...

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):
Don't believe there is anything in my config to control this; autodiscovery of cast devices is used to control ?

tts:
  - platform: google_translate
    service_name: google_say

logger:
  default: info
  logs:
    homeassistant.components.cast: debug
    homeassistant.components.cast.media_player: debug
    homeassistant.component.life360: debug
    homeassistant.component.life360.device_tracker: debug
    pychromecast: debug
    pychromecast.discovery: debug
    pychromecast.socket_client: debug

Traceback (if applicable):

Traceback (most recent call last):
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/homeassistant/components/websocket_api/commands.py", line 130, in handle_call_service
    connection.context(msg),
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/homeassistant/core.py", line 1235, in async_call
    await asyncio.shield(self._execute_service(handler, service_call))
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/homeassistant/core.py", line 1260, in _execute_service
    await handler.func(service_call)
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/homeassistant/components/tts/__init__.py", line 165, in async_say_handle
    DOMAIN_MP, SERVICE_PLAY_MEDIA, data, blocking=True
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/homeassistant/core.py", line 1235, in async_call
    await asyncio.shield(self._execute_service(handler, service_call))
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/homeassistant/core.py", line 1260, in _execute_service
    await handler.func(service_call)
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity_component.py", line 210, in handle_service
    self._platforms.values(), func, call, service_name, required_features
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/service.py", line 349, in entity_service_call
    future.result()  # pop exception if have
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/service.py", line 373, in _handle_service_platform_call
    await func(entity, data)
  File "/usr/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/homeassistant/components/cast/media_player.py", line 1052, in play_media
    self._chromecast.media_controller.play_media(media_id, media_type)
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/pychromecast/controllers/media.py", line 523, in play_media
    callback_function=app_launched_callback)
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/pychromecast/socket_client.py", line 935, in launch_app
    self.update_status(lambda response:
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/pychromecast/socket_client.py", line 926, in update_status
    callback_function=callback_function_param)
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/pychromecast/controllers/__init__.py", line 84, in send_message
    self.namespace, data, inc_session_id, callback_function)
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/pychromecast/socket_client.py", line 725, in send_platform_message
    inc_session_id, callback_function_param)
  File "/home/vmware/homeassistant/lib/python3.6/site-packages/pychromecast/socket_client.py", line 719, in send_message
    str(self.port) + " is connecting...")

Additional information:

I really hope that the HA team can have this gracefully fail, meaning send a notice to the GUI, but then force a restart rather than letting it hang forever!

Once this start happening, i have to restart HA :(

[emontnemery]

@marc-gist Can you please clarify when this happens, is it only if you try to use tts functionality?

[marc-gist]

I only really use Google cast for TTS; so yes... however, once I get this error; using the device via the Web UI (click the "power on" button from the UI on the media player integration page, will throw this error. I lose all connectivity to the device until I restart HA.

Sometimes it happens within a day of resting. sometimes I get a week... All cast devices are setup with static IPs (dhcp reservation). and as stated above, all other control of the device outside of HA works fine.

[stale[bot]]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[marc-gist]

still not solved. worse actually with latest HA!

[scaarup]

Yeah this is really bad. Also happening a lot more in the later versions. I have to restart HA at least a couple of times a week to recover.

[Kanishkaz]

I have the exact same issue. It's more frequent since upgrading to 103.

[DhKDc]

Same here and it jus crash my HA instance with not any fatal error. it just simply stops working. Disabled the Google Cast integration and everything workin without errors for 4 days.

[ChrisJohns-me]

Same. Getting this "pychromecast.error.NotConnected: Chromecast x.x.x.x:8009 is connecting..." issue on v0.105.2

[scaarup]

This is just getting more and more annoying...

[leifan78]

On version 0.106.6 and having the same problem.
Only restart of home assistant helps.

[hemantkamalakar]

I am on hassio version 0.107.7 and having the same problem. It requires restart of home-assistant to get it working.

[emontnemery]

Please help to collect debug log:

• Enable debug logging for the cast integration and its dependencies:
  Logger options in configuration.yaml
yaml 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
• When the issue is reproduced:
  a. Use the Google home app to verify that the Google home app can reach each cast to which the connection is lost, and also confirm the IP address of each disconnected cast (found at the end of the device settings menu in the Google Home App). Note the time and confirmed IP address. Please note that sharing of private IP addresses such as 192.168.x.x or 10.x.x.x is not a security issue as those IPs are only accessible within your own network.
  b. Restart HA to recover connection to the cast
  c. Add a comment to this issue including:
  
  
  
  • The time at which connection to the casts is lost
  
  
  • The name of the casts that are turned on but can't be connected to by HA
  
  
  • The IP addresses manually checked for each failing cast, and the time of checking
  
  
  • A complete HA log - from start of HA until connection is lost and HA is restarted and the connections to the casts are reestablished. The log can be uploaded to https://gist.github.com/ or similar service, or attached as a file.
  
  
  • Describe if you have manually configured the casts in configuration.yaml or if the casts have been discovered.
  
  

If you're not comfortable with sharing a log publicly, please ping me on discord.

[scaarup]

On it!

[leifan78]

Hi

Thank for the feedback.

I have added the debug. Will report back next time I see it.

Venlig Hilsen / Best regardsLeif A. NielsenEmail: [email protected]

On 6 April 2020 at 09:53:34 +02:00, Erik Montnemery [e-mail] wrote:

Please help to collect debug log:

• Enable debug logging for the cast integration and its dependencies:
  Logger options in configuration.yaml

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

• When the issue is reproduced:
  a. Use the Google home app to verify that the Google home app can reach each cast to which the connection is lost, and also confirm the IP address of each disconnected cast (found at the end of the device settings menu in the Google Home App). Note the time and confirmed IP address. Please note that sharing of private IP addresses such as 192.168.x.x or 10.x.x.x is not a security issue as those IPs are only accessible within your own network.
  b. Restart HA to recover connection to the cast
  c. Add a comment to this issue including:

  • The time at which connection to the casts is lost
  • The name of the casts that are turned on but can't be connected to by HA
  • The IP addresses manually checked for each failing cast, and the time of checking
  • A complete HA log - from start of HA until connection is lost and HA is restarted and the connections to the casts are reestablished. The log can be uploaded to https://gist.github.com/ or similar service, or attached as a file.
  • Describe if you have manually configured the casts in configuration.yaml or if the casts have been discovered.
    If you're not comfortable with sharing a log publicly, please ping me on discord.

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/27094#issuecomment-609634527, or unsubscribe https://github.com/notifications/unsubscribe-auth/AKL7DIOHDD7JWOD4DL2YE53RLGC75ANCNFSM4I4ITJDQ.

[dadukhankevin]

What fixed mine was instead of calling cast.start() I called cast.wait() instead.

[emontnemery]

@dadukhankevin Can you elaborate a bit please, which file did you modify and where?

[emontnemery]

@marc-gist in the issue description, you mention you have debug logging enabled for the cast integration and pychromecast. Do you have a full log you can share, the short snippet included in the description is unfortunately not enough.

[dadukhankevin]

@emontnemery So I am not using home-assistant, I'm just using pychromecast. for some reason when connecting to the cast I had to use cast.wait() and not cast.start(). I have no idea why. Here is the code:

# This does not work 
import pychromecast
cast = pychromecast.get_chromecasts()[0]
cast.start()  # pychromecast.error.NotConnected: Chromecast...
cast.play_media('example.png', content_type='image/png')

#**This does**
import pychromecast

cast = pychromecast.get_chromecasts()[0]
cast.wait()  # connects
cast.play_media('example.png', content_type='image/png')

[emontnemery]

@dadukhankevin OK, I see.
cast.start() starts the Chromecast object's work thread.
cast.wait() starts the Chromecast object's work thread _and wait's for a successful connection and status update._
cast.play_media requires an established connection to the cast device to work.
Hence, it's expected that your script won't work if you call cast.start() and then immediately call cast.play_media.

Your observation is not related to the problem reported in this issue, but thanks for the input.

[leifan78]

@emontnemery

I have now uploaded a complete HA log where the problem is reproduced.
https://gist.github.com/leifan78/e59829d745f82e2f365e8a7138406a82

• a: The IP of the disconnected cast is: 192.168.0.157 checked minutes after failing and while failing
• b: It is not responding to any command what so ever but I tried this one: https://dr05-lh.akamaihd.net/i/live/dr05_0@147058/master.m3u8
• c: I noticed the fault when trying to stop cast at around the time 19:30. The one at 192.168.0.157 was the only one left on the rest was turned off.
  No manual configuration is made.

Hope it helps

BR Leif

[emontnemery]

@leifan78 Thanks! It seems the full log is not available in the gist, the last line is timestamped "2020-04-27 13:41:53 DEBUG".
Can you double check please?

Edit: It seems the full log is available in a previous version of the gist. I think this should be enough.

[leifan78]

@emontnemery

Yes, I see. It is updated now. The last part was cut off by gist.

[emontnemery]

@leifan78 It seems the pychromecast's worker thread is either silently exiting or deadlocked/stuck.

Would you mind applying this patch https://github.com/emontnemery/pychromecast/commit/30ec553544980a40fcf4d358b8340d0587435164 and try to reproduce again?
This won't fix anything, but with a little luck help diagnose the problem.

[leifan78]

@emontnemery
Okay I see. I have found a way to reproduce it it just seems to pop up once in while.
I will try to apply the patch. Sorry for my ignorance but the easiest and best way is ssh and Vi to apply the patch?

[emontnemery]

@leifan78 Yeah, I think ssh + vi is OK to manually apply the changes.

By the way, which version of home assistant and pychromecast are you on?
To check pychromecast version:
cat homeassistant/components/cast/manifest.json | grep requirements

[leifan78]

@emontnemery

I will get the patch applied. I am on Home assistant version 0.108.8.
["pychromecast==4.2.0"]

[leifan78]

@emontnemery

My socket_client.py file is very different from the one you. Can I replace the whole file?
Is the patch "compatible" with my version?
My socket_client.py file

[emontnemery]

@leifan78 yes, it should be fine since the patch is just additional prints. Replacing the entire file won't work.

[emontnemery]

@leifan78 Did you manage to apply the patch?

[leifan78]

@emontnemery

I have update HA and thereby pychromecast.
"requirements": ["pychromecast==5.0.0"],
Home Assistant 0.109.3
I am now running with the additional debug you added in.
I will feedback next time I get the alarm.

[emontnemery]

@marc-gist Do you still have this problem? Would you mind adding the additional debug also?

[marc-gist]

@marc-gist Do you still have this problem? Would you mind adding the additional debug also?

I gave up on HA some time ago... I can try again and see if things have improved. I really appreciate the check-in and work on this. would be nice to go back to one solution :)

[dima-ser]

Also getting the same error when casting in HA:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 130, in handle_call_service
    connection.context(msg),
  File "/usr/src/homeassistant/homeassistant/core.py", line 1260, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1295, in _execute_service
    await handler.func(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 209, in handle_service
    self._platforms.values(), func, call, required_features
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 454, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 597, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 485, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/camera/__init__.py", line 701, in async_handle_play_stream_service
    DOMAIN_MP, SERVICE_PLAY_MEDIA, data, blocking=True, context=service_call.context
  File "/usr/src/homeassistant/homeassistant/core.py", line 1260, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1295, in _execute_service
    await handler.func(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 209, in handle_service
    self._platforms.values(), func, call, required_features
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 454, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 597, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 485, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/media_player/__init__.py", line 604, in async_play_media
    ft.partial(self.play_media, media_type, media_id, **kwargs)
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/cast/media_player.py", line 510, in play_media
    self._chromecast.media_controller.play_media(media_id, media_type)
  File "/usr/local/lib/python3.7/site-packages/pychromecast/controllers/media.py", line 546, in play_media
    receiver_ctrl.launch_app(self.app_id, callback_function=app_launched_callback)
  File "/usr/local/lib/python3.7/site-packages/pychromecast/socket_client.py", line 1132, in launch_app
    self._send_launch_message(app_id, force_launch, callback_function)
  File "/usr/local/lib/python3.7/site-packages/pychromecast/socket_client.py", line 1143, in _send_launch_message
    self.send_message({MESSAGE_TYPE: TYPE_LAUNCH, APP_ID: app_id})
  File "/usr/local/lib/python3.7/site-packages/pychromecast/controllers/__init__.py", line 90, in send_message
    self.send_message_nocheck(data, inc_session_id, callback_function)
  File "/usr/local/lib/python3.7/site-packages/pychromecast/controllers/__init__.py", line 94, in send_message_nocheck
    self._message_func(self.namespace, data, inc_session_id, callback_function)
  File "/usr/local/lib/python3.7/site-packages/pychromecast/socket_client.py", line 896, in send_platform_message
    callback_function_param,
  File "/usr/local/lib/python3.7/site-packages/pychromecast/socket_client.py", line 884, in send_message
    "Chromecast {}:{} is connecting...".format(self.host, self.port)
pychromecast.error.NotConnected: Chromecast [IP:PORT REDACTED] is connecting...

[emontnemery]

@dima-ser Do you have some way of reproducing the problem?

[dima-ser]

No, I don't know how to reliably reproduce it, I would need more testing. I was casting a camera to my Shield TV from HA and it was working fine. I then did TTS test and it was working fine. Then I attempted to cast camera again and got this error. Now I can't cast camera or TTS, it throws this error.

[emontnemery]

OK.

If you have time, please try to reproduce with this patch: https://github.com/emontnemery/pychromecast/commit/30ec553544980a40fcf4d358b8340d0587435164
Note that you should NOT replace the entire file, just apply the changes.

[dima-ser]

OK.

If you have time, please try to reproduce with this patch: emontnemery/pychromecast@30ec553
Note that you should NOT replace the entire file, just apply the changes.

How do I apply it? I run HA in Docker.

[emontnemery]

I think you can ssh in to the container and modify the file, but I'm not really sure.

[dima-ser]

I think you can ssh in to the container and modify the file, but I'm not really sure.

What's the path of the file I need to edit?

[emontnemery]

The change is officially released in pychromecast 7.1.1.
You need to modify homeassistant/components/cast/manifest.json and bump pychromecast to 7.1.1
After restarting HA, it should upgrade pychromecast to 7.1.1

You also need to modify:

diff --git a/homeassistant/components/cast/media_player.py b/homeassistant/components/cast/media_player.py
index 3883c5ad72..f512d315e9 100644
--- a/homeassistant/components/cast/media_player.py
+++ b/homeassistant/components/cast/media_player.py
@@ -283,6 +283,8 @@ class CastDevice(MediaPlayerEntity):
                 cast_info.uuid,
                 cast_info.model_name,
                 cast_info.friendly_name,
+                None,
+                None,
             ),
             ChromeCastZeroconf.get_zeroconf(),
         )

[ekkesa]

I'm having the same problem. It requires restart of home-assistant to get it working again.

[scaarup]

I am running Hassio. Will these fixes be released soon, or do I need to manually edit files?

[emontnemery]

@ekkesa, @scaarup Unfortunately, no one has provided a useful log capturing the issue and I have not been able to reproduce it myself.
If you can reproduce the problem, it would be highly appreciated if you can collect logs as requested here: https://github.com/home-assistant/core/issues/27094#issuecomment-609634527

[ekkesa]

@emontnemery I have enabled the collection of logs - The issue is random and usually only discovered once something stop working - It will be difficult to pinpoint the exact time.

[emontnemery]

The issue is random and usually only discovered once something stop working

That's fine as long as you can upload a log covering the time where the Chromecast stops working.

[scaarup]

@emontnemery I have some logs now.
home-assistant-restarted.log
home-assistant-broken-cast.log
My chromecast is at 192.168.49.143.
The entity id is "media_player.stuen". Name is "Stuen"
I noticed it was not working at 2020-08-14 19:06:17.
It is not configured manually

[emontnemery]

Thanks! Which cast is it that fails, is it the one named "Stuen"?

[scaarup]

Thanks! Which cast is it that fails, is it the one named "Stuen"?

Yeah, that's the one.

[emontnemery]

Great!
The problem in the log is that a message received from an Axis Chromecast app is assumed to be a valid dict which it's not.
It should mean that you can reproduce the problem by messing around a bit with the Axis Chromecast app, is that the case?

You can try applying the change here to pychromecast https://github.com/home-assistant-libs/pychromecast/pull/405, which should fix your problem.

[scaarup]

"Axis Chromecast app" doesn't ring a bell... Wonder if it is a different name for my "DR TV app", which I often use to cast from.
Can I apply that patch in an easy way? I am running HassIO.

[emontnemery]

Yes, it might be the "DR TV app", there's this PR https://github.com/home-assistant-libs/pychromecast/pull/363 which does something very similar.

I'm not sure what the easiest way is to patch on HassIO.

[scaarup]

Are we verifying if this solves the issue before anything gets into HA?

[Ebbe]

The fix in 7.2.1. works for me (using DR TV)

[scaarup]

@Ebbe awesome, looking forward to that.

[Ebbe]

What's working @Ebbe - the patch or is DR TV not causing you any problems?

The patch. I had the same problem as you before, but with the new version (7.2.1) it's gone.
The disconnect always happened when I was playing a series, and chromecast was about to play the next episode.

PS. A new version of Home assistant is currently being build with this fix: https://www.home-assistant.io/blog/2020/08/12/release-114/#release-01143---august-20

[scaarup]

Good catch! I was unable to figure out what caused this.
Yeah I can see the new release is out, so waiting for it to pop up in Supervisor :).

[emontnemery]

I'm closing this issue as one case triggering it was merged in #39018.
If it's still seen, please comment or (preferably) open a new issue.

[scaarup]

I have not encountered any problems after upgrading :). Thanks vey much.