Fix chromecast disconnect

[awarecan]

Description:

Overhaul the platform setup code.

Chromecast has two different way to config, zeroconf discovery or manual config the host IP. In this PR

1. Delay the start of internal discovery till HA is started
2. Auto-discovery device could be discovery again if it came back after offline, so limit the socket connection retry times
3. For all manual configured host IP, HA will create media_player device no matter the device is online or not during the system start up. The socket connection will "keep-alive", e.g. keep trying to connect to host until it connected. If the connection lost, it will keep trying to reconnect

Related issue (if applicable): fixes #13530 fixes #16686

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

Example entry for configuration.yaml (if applicable):

# Either configured through configuration panel or by configuration.yaml
# configuration.yaml example
cast:
  media_player:
    - host: 192.168.1.1
    - host: 192.168.1.2

Checklist:

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

[awarecan]

Consider the complex of configuration and multiple chromecast device types, I am asking help for testing.

When you are testing, please enable debug log.

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

[balloob]

Why would we wait till start? That's generally a bad idea because that's when automations start, so any device discovered after that could trigger an automation.

[edif30]

Working with @awarecan on testing. Initially after a 30 min duration of a cast device being offline and replugging back in the # on the return in line 127 seemed to allow the cast device to become available again. But after a much longer test (several hours), 3 devices dropped and never came back into an available state. I provided the entire log to @awarecan. I also disagree on delaying the internal start of discovery.

[awarecan]

Many thanks to @edif30

The log was under a different version changes, not this PR, but the basic change of rediscover logic is the same thing.

And I found an interesting race condition in the disconnection event, row log is

2018-09-22 02:21:08 DEBUG (Thread-14) [pychromecast.socket_client] Received unknown namespace: Message urn:x-cast:com.google.cast.multizone from receiver-0 to *: {'deviceId': 'b968b6c5-xxxx-xxxx-xxxx-7eaf54a522ab', 'requestId': 0, 'type': 'DEVICE_REMOVED'}
2018-09-22 02:21:08 DEBUG (Thread-24) [pychromecast.socket_client] Received unknown namespace: Message urn:x-cast:com.google.cast.multizone from receiver-0 to *: {'deviceId': 'b968b6c5-xxxx-xxxx-xxxx-7eaf54a522ab', 'requestId': 0, 'type': 'DEVICE_REMOVED'}
2018-09-22 02:21:08 DEBUG (Thread-24) [pychromecast.socket_client] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to *: {'requestId': 0, 'status': {'userEq': {'high_shelf': {'frequency': 4500.0, 'gain_db': 0.0, 'quality': 0.707}, 'low_shelf': {'frequency': 150.0, 'gain_db': 0.0, 'quality': 0.707}, 'max_peaking_eqs': 0, 'peaking_eqs': []}, 'volume': {'controlType': 'master', 'level': 0.32500001788139343, 'muted': False, 'stepInterval': 0.05000000074505806}}, 'type': 'RECEIVER_STATUS'}
2018-09-22 02:21:08 DEBUG (Thread-24) [pychromecast.controllers] Received status: CastStatus(is_active_input=None, is_stand_by=None, volume_level=0.32500001788139343, volume_muted=False, app_id=None, display_name=None, namespaces=[], session_id=None, transport_id=None, status_text='')
2018-09-22 02:21:36 WARNING (Thread-21) [pychromecast.socket_client] Heartbeat timeout, resetting connection
2018-09-22 02:21:36 DEBUG (Thread-21) [pychromecast.socket_client] connection listener: 7f34b847f748 (CastStatusListener)
2018-09-22 02:21:36 DEBUG (Thread-21) [homeassistant.components.media_player.cast] Received cast device connection status: LOST
2018-09-22 02:21:36 DEBUG (Thread-21) [homeassistant.components.media_player.cast] Cast device availability changed: LOST
2018-09-22 02:21:36 DEBUG (Thread-21) [pychromecast.socket_client] connection listener: 7f34b847f748 (CastStatusListener)
2018-09-22 02:21:36 DEBUG (Thread-21) [homeassistant.components.media_player.cast] Received cast device connection status: CONNECTING
2018-09-22 02:21:46 DEBUG (Thread-21) [pychromecast.socket_client] connection listener: 7f34b847f748 (CastStatusListener)
2018-09-22 02:21:46 DEBUG (Thread-21) [homeassistant.components.media_player.cast] Received cast device connection status: FAILED
2018-09-22 02:21:46 ERROR (Thread-21) [pychromecast.socket_client] Failed to connect, retrying in 2.0s
2018-09-22 02:21:48 DEBUG (Thread-21) [pychromecast.socket_client] connection listener: 7f34b847f748 (CastStatusListener)
2018-09-22 02:21:48 DEBUG (Thread-21) [homeassistant.components.media_player.cast] Received cast device connection status: CONNECTING
2018-09-22 02:21:48 DEBUG (Thread-21) [pychromecast.socket_client] connection listener: 7f34b847f748 (CastStatusListener)
2018-09-22 02:21:48 DEBUG (Thread-21) [homeassistant.components.media_player.cast] Received cast device connection status: FAILED
2018-09-22 02:21:48 DEBUG (Thread-21) [pychromecast.socket_client] Failed to connect, retrying in 2.0s
2018-09-22 02:21:50 DEBUG (zeroconf-ServiceBrowser__googlecast._tcp.local.) [homeassistant.components.media_player.cast] Discovered previous chromecast ChromecastInfo(host='192.168.100.45', port=8009, uuid='b968b6c5-xxxx-xxxx-xxxx-7eaf54a522ab', manufacturer='', model_name='Google Home Mini', friendly_name='Office Home Mini')
2018-09-22 02:21:50 DEBUG (zeroconf-ServiceBrowser__googlecast._tcp.local.) [homeassistant.components.media_player.cast] Discovered chromecast ChromecastInfo(host='192.168.100.45', port=8009, uuid='b968b6c5-xxxx-xxxx-xxxx-7eaf54a522ab', manufacturer='', model_name='Google Home Mini', friendly_name='Office Home Mini')
2018-09-22 02:21:50 DEBUG (MainThread) [homeassistant.components.media_player.cast] Discovered chromecast with same UUID: ChromecastInfo(host='192.168.100.45', port=8009, uuid='b968b6c5-xxxx-xxxx-xxxx-7eaf54a522ab', manufacturer='', model_name='Google Home Mini', friendly_name='Office Home Mini')
2018-09-22 02:21:50 DEBUG (MainThread) [homeassistant.components.media_player.cast] No connection related update: ('192.168.100.45', 8009)
2018-09-22 02:21:50 DEBUG (Thread-21) [pychromecast.socket_client] connection listener: 7f34b847f748 (CastStatusListener)
2018-09-22 02:21:50 DEBUG (Thread-21) [homeassistant.components.media_player.cast] Received cast device connection status: CONNECTING
2018-09-22 02:21:50 DEBUG (Thread-21) [pychromecast.socket_client] connection listener: 7f34b847f748 (CastStatusListener)
2018-09-22 02:21:50 DEBUG (Thread-21) [homeassistant.components.media_player.cast] Received cast device connection status: FAILED
2018-09-22 02:21:50 ERROR (Thread-21) [pychromecast.socket_client] Failed to connect. No retries.
2018-09-22 02:21:50 DEBUG (Thread-21) [pychromecast.socket_client] connection listener: 7f34b847f748 (CastStatusListener)
2018-09-22 02:21:50 DEBUG (Thread-21) [homeassistant.components.media_player.cast] Received cast device connection status: DISCONNECTED
2018-09-22 02:22:05 DEBUG (Thread-14) [pychromecast.socket_client] Received unknown namespace: Message urn:x-cast:com.google.cast.multizone from receiver-0 to *: {'device': {'capabilities': 4, 'deviceId': 'b968b6c5-xxxx-xxxx-xxxx-7eaf54a522ab', 'name': 'Office Home Mini', 'volume': {'level': 0.4000000059604645, 'muted': False}}, 'requestId': 0, 'type': 'DEVICE_ADDED'}
2018-09-22 02:22:05 DEBUG (Thread-24) [pychromecast.socket_client] Received unknown namespace: Message urn:x-cast:com.google.cast.multizone from receiver-0 to *: {'device': {'capabilities': 4, 'deviceId': 'b968b6c5-xxxx-xxxx-xxxx-7eaf54a522ab', 'name': 'Office Home Mini', 'volume': {'level': 0.4000000059604645, 'muted': False}}, 'requestId': 0, 'type': 'DEVICE_ADDED'}

At 02:21:08, this device was removed, at 02:21:36 HA aware that disconnection and start re-connection attempt. At 02:21:50, zeroconf discovered device back, HA think No connection related update: ('192.168.100.45', 8009) because the previous open socket is still reconnecting. At the exactly same second, the re-connection failed and reach the max retry and stopped. Therefore, this device is lost

At 02:22:05, two other device in same multizone group received DEVICE_ADDED message

I am thinking, after the zeroconf discovered the device, the device may not be able to connect immediately, maybe we should close the previous socket no matter when we discovered new or previous device.

By the way, this log was still in 3 retires version. This PR already changed the retry times to 6, hope it can workaround this particular issue.

[benjamin1492]

These logs are from commit 92cb07a. I did one log with the group discovery turned off and the other with it turned on.
home-assistant_groups_enabled.log
home-assistant_no_groups.log

[edif30]

@awarecan I ended up reverting that retry back to 3 just to test with the removal of the return on line 127. I didn't see a difference between the two on long outage durations of cast devices.

[awarecan]

I changed fix. New PR is #16804.