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

Fix chromecast re-connection issue #16732

Merged
merged 1 commit into from Sep 20, 2018

Conversation

Projects
None yet
9 participants
@awarecan
Contributor

awarecan commented Sep 20, 2018

Description:

Since change of #16471, the cast status listener will receive CONNECTION_STATUS_DISCONNECTED status change call back. We should do disconnection clean up in the call back to allow re-connection logic works

Related issue (if applicable): fixes #16686

Pull request in home-assistant.github.io with documentation (if applicable): home-assistant/home-assistant.github.io#<home-assistant.github.io PR number goes here>

Example entry for configuration.yaml (if applicable):

Checklist:

  • The code change is tested and works locally.
  • Local tests pass with tox. Your PR cannot be merged unless tests pass
@awarecan

This comment has been minimized.

Contributor

awarecan commented Sep 20, 2018

Some local test logs for reference, for quick debugging, reconnection params changed to

CONNECTION_RETRY = 1
CONNECTION_RETRY_WAIT = 1
CONNECTION_TIMEOUT = 3

HA startup with chromecast offline, no blocking

2018-09-19 23:35:20 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.cast
2018-09-19 23:35:20 DEBUG (SyncWorker_2) [homeassistant.components.media_player.cast] Starting internal pychromecast discovery.
2018-09-19 23:35:20 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 0.41s
2018-09-19 23:35:20 INFO (MainThread) [homeassistant.core] Starting Home Assistant
2018-09-19 23:35:20 INFO (MainThread) [homeassistant.core] Timer:starting
2018-09-19 23:35:25 INFO (MainThread) [homeassistant.components.http.view] Serving /api/websocket to 192.168.182.1 (auth: False)

Plug on chromecast, HA discovered device

2018-09-19 23:36:12 DEBUG (zeroconf-ServiceBrowser__googlecast._tcp.local.) [homeassistant.components.media_player.cast] Discovered chromecast ChromecastInfo(host='192.168.86.29', port=8009, uuid='da3e00ce-xxxx', manufacturer='Google Inc.', model_name='Chromecast', friendly_name='Office TV')
2018-09-19 23:36:12 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connecting to cast device ChromecastInfo(host='192.168.86.29', port=8009, uuid='da3e00ce-xxxx', manufacturer='Google Inc.', model_name='Chromecast', friendly_name='Office TV')
2018-09-19 23:36:12 INFO (SyncWorker_6) [pychromecast] Querying device status
2018-09-19 23:36:12 DEBUG (SyncWorker_6) [pychromecast.controllers] Receiver:Updating status
2018-09-19 23:36:12 DEBUG (SyncWorker_6) [pychromecast.socket_client] Sending: Message urn:x-cast:com.google.cast.tp.connection from sender-0 to receiver-0: {'type': 'CONNECT', 'origin': {}, 'userAgent': 'PyChromecast', 'senderInfo': {'sdkType': 2, 'version': '15.605.1.3', 'browserVersion': '44.0.2403.30', 'platform': 4, 'systemVersion': 'Macintosh; Intel Mac OS X10_10_3', 'connectionType': 1}}
2018-09-19 23:36:12 DEBUG (SyncWorker_6) [pychromecast.socket_client] Sending: Message urn:x-cast:com.google.cast.receiver from sender-0 to receiver-0: {'type': 'GET_STATUS', 'requestId': 1}
2018-09-19 23:36:12 DEBUG (SyncWorker_6) [pychromecast.socket_client] Connected!
2018-09-19 23:36:12 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connection successful!
2018-09-19 23:36:12 DEBUG (Thread-2) [pychromecast.socket_client] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to sender-0: {'requestId': 1, 'status': {'applications': [{'appId': 'E8C28D3C', 'displayName': 'Backdrop', 'isIdleScreen': True, 'launchedFromCloud': False, 'namespaces': [{'name': 'urn:x-cast:com.google.cast.debugoverlay'}, {'name': 'urn:x-cast:com.google.cast.cac'}, {'name': 'urn:x-cast:com.google.cast.sse'}, {'name': 'urn:x-cast:com.google.cast.remotecontrol'}], 'sessionId': '55d5aa57-19f6-4fd7-9784-135b25660720', 'statusText': '', 'transportId': '55d5aa57-19f6-4fd7-9784-135b25660720'}], 'userEq': {}, 'volume': {'controlType': 'attenuation', 'level': 1.0, 'muted': False, 'stepInterval': 0.05000000074505806}}, 'type': 'RECEIVER_STATUS'}
2018-09-19 23:36:12 DEBUG (Thread-2) [pychromecast.controllers] Received status: CastStatus(is_active_input=False, is_stand_by=True, volume_level=1.0, volume_muted=False, app_id='E8C28D3C', display_name='Backdrop', namespaces=['urn:x-cast:com.google.cast.debugoverlay', 'urn:x-cast:com.google.cast.cac', 'urn:x-cast:com.google.cast.sse', 'urn:x-cast:com.google.cast.remotecontrol'], session_id='55d5aa57-19f6-4fd7-9784-135b25660720', transport_id='55d5aa57-19f6-4fd7-9784-135b25660720', status_text='')

Plug off chromecast, HA received DISCONNECTED event

2018-09-19 23:36:53 WARNING (Thread-2) [pychromecast.socket_client] Heartbeat timeout, resetting connection
2018-09-19 23:36:53 DEBUG (Thread-2) [pychromecast.socket_client] connection listener: 7fd750931198 (CastStatusListener)
2018-09-19 23:36:53 DEBUG (Thread-2) [homeassistant.components.media_player.cast] Received cast device connection status: LOST
2018-09-19 23:36:53 DEBUG (Thread-2) [homeassistant.components.media_player.cast] Cast device availability changed: LOST
2018-09-19 23:36:53 DEBUG (Thread-2) [pychromecast.socket_client] connection listener: 7fd750931198 (CastStatusListener)
2018-09-19 23:36:53 DEBUG (Thread-2) [homeassistant.components.media_player.cast] Received cast device connection status: CONNECTING
2018-09-19 23:36:56 DEBUG (Thread-2) [pychromecast.socket_client] connection listener: 7fd750931198 (CastStatusListener)
2018-09-19 23:36:56 DEBUG (Thread-2) [homeassistant.components.media_player.cast] Received cast device connection status: FAILED
2018-09-19 23:36:56 ERROR (Thread-2) [pychromecast.socket_client] Failed to connect. No retries.
2018-09-19 23:36:56 DEBUG (Thread-2) [pychromecast.socket_client] connection listener: 7fd750931198 (CastStatusListener)
2018-09-19 23:36:56 DEBUG (Thread-2) [homeassistant.components.media_player.cast] Received cast device connection status: DISCONNECTED

Plug on again

2018-09-19 23:37:52 DEBUG (zeroconf-ServiceBrowser__googlecast._tcp.local.) [homeassistant.components.media_player.cast] Discovered chromecast ChromecastInfo(host='192.168.86.29', port=8009, uuid='da3e00ce-xxxx', manufacturer='', model_name='Chromecast', friendly_name='Office TV')
2018-09-19 23:37:52 DEBUG (MainThread) [homeassistant.components.media_player.cast] Discovered chromecast with same UUID: ChromecastInfo(host='192.168.86.29', port=8009, uuid='da3e00ce-xxxx', manufacturer='', model_name='Chromecast', friendly_name='Office TV')
2018-09-19 23:37:52 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connecting to cast device ChromecastInfo(host='192.168.86.29', port=8009, uuid='da3e00ce-xxxx', manufacturer='', model_name='Chromecast', friendly_name='Office TV')
2018-09-19 23:37:52 INFO (SyncWorker_0) [pychromecast] Querying device status
2018-09-19 23:37:52 DEBUG (SyncWorker_0) [pychromecast.controllers] Receiver:Updating status
2018-09-19 23:37:52 DEBUG (SyncWorker_0) [pychromecast.socket_client] Sending: Message urn:x-cast:com.google.cast.tp.connection from sender-0 to receiver-0: {'type': 'CONNECT', 'origin': {}, 'userAgent': 'PyChromecast', 'senderInfo': {'sdkType': 2, 'version': '15.605.1.3', 'browserVersion': '44.0.2403.30', 'platform': 4, 'systemVersion': 'Macintosh; Intel Mac OS X10_10_3', 'connectionType': 1}}
2018-09-19 23:37:52 DEBUG (SyncWorker_0) [pychromecast.socket_client] Sending: Message urn:x-cast:com.google.cast.receiver from sender-0 to receiver-0: {'type': 'GET_STATUS', 'requestId': 1}
2018-09-19 23:37:52 DEBUG (SyncWorker_0) [pychromecast.socket_client] Connected!
2018-09-19 23:37:52 DEBUG (MainThread) [homeassistant.components.media_player.cast] Connection successful!
2018-09-19 23:37:52 DEBUG (Thread-3) [pychromecast.socket_client] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to sender-0: {'requestId': 1, 'status': {'applications': [{'appId': 'E8C28D3C', 'displayName': 'Backdrop', 'isIdleScreen': True, 'launchedFromCloud': False, 'namespaces': [{'name': 'urn:x-cast:com.google.cast.debugoverlay'}, {'name': 'urn:x-cast:com.google.cast.cac'}, {'name': 'urn:x-cast:com.google.cast.sse'}, {'name': 'urn:x-cast:com.google.cast.remotecontrol'}], 'sessionId': 'e9fdf885-ab4e-467c-83f6-416ae7392b48', 'statusText': '', 'transportId': 'e9fdf885-ab4e-467c-83f6-416ae7392b48'}], 'userEq': {}, 'volume': {'controlType': 'attenuation', 'level': 1.0, 'muted': False, 'stepInterval': 0.05000000074505806}}, 'type': 'RECEIVER_STATUS'}
2018-09-19 23:37:52 DEBUG (Thread-3) [pychromecast.controllers] Received status: CastStatus(is_active_input=False, is_stand_by=True, volume_level=1.0, volume_muted=False, app_id='E8C28D3C', display_name='Backdrop', namespaces=['urn:x-cast:com.google.cast.debugoverlay', 'urn:x-cast:com.google.cast.cac', 'urn:x-cast:com.google.cast.sse', 'urn:x-cast:com.google.cast.remotecontrol'], session_id='e9fdf885-ab4e-467c-83f6-416ae7392b48', transport_id='e9fdf885-ab4e-467c-83f6-416ae7392b48', status_text='')
@mh-daedalus

This comment has been minimized.

mh-daedalus commented Sep 20, 2018

I've pushed it to my environment, I'll let you know if I see something out of the ordinary with my debugs compared to yours.

@balloob balloob added this to the 0.78.1 milestone Sep 20, 2018

@balloob balloob merged commit 3a45481 into home-assistant:dev Sep 20, 2018

5 checks passed

Hound No violations found. Woof!
WIP ready for review
Details
cla-bot Everyone involved has signed the CLA
continuous-integration/travis-ci/pr The Travis CI build passed
Details
coverage/coveralls Coverage remained the same at 93.545%
Details

@wafflebot wafflebot bot removed the in progress label Sep 20, 2018

balloob added a commit that referenced this pull request Sep 20, 2018

@balloob balloob referenced this pull request Sep 20, 2018

Merged

0.78.1 #16742

@bachoo786

This comment has been minimized.

bachoo786 commented Sep 22, 2018

I am still having Chromecast issues says unavailable have updated HA to 0.78.3. It starts working again until I reboot HA.

@kiwinol

This comment has been minimized.

kiwinol commented Sep 23, 2018

I am also still having issues. My Chromcast seems to disconnect at night

Failed to connect. No retries.

03:50 /usr/local/lib/python3.6/site-packages/pychromecast/socket_client.py (ERROR)

@bachoo786

This comment has been minimized.

bachoo786 commented Sep 23, 2018

Same issue as @kiwinol

@ryanmelt

This comment has been minimized.

ryanmelt commented Sep 24, 2018

This change seems to make my google home minis disconnect and become unavailable overnight. 👎

@SteveDinn

This comment has been minimized.

SteveDinn commented Sep 26, 2018

Same here. I'm on 0.78.2, and my cast devices remain at 'unavailable' after they are offline for updates.

@MartinHjelmare

This comment has been minimized.

Member

MartinHjelmare commented Sep 26, 2018

Please keep the feedback in #16686.

@home-assistant home-assistant locked as resolved and limited conversation to collaborators Sep 26, 2018

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.