14.0.2 sometimes fails to play media in Home Assistant

bdraco commented 1 month ago

https://github.com/home-assistant/core/pull/127555

Tried to reproduce with

action: media_player.play_media
data:
  media_content_id: >-
    https://file-examples.com/storage/fe36b23e6a66fc0679c1f86/2017/11/file_example_MP3_1MG.mp3
  media_content_type: music
target:
  entity_id: media_player.living_room_tv

Can repro with debug off for pychromecast after 8-10 attempts. With debug logging turned on I cannot reproduce so its some type of race

bdraco commented 1 month ago

I've rebooted 3 times now and cannot reproduce anymore

bdraco commented 1 month ago

Maybe the device needs to be idle for a bit before it can happen

bdraco commented 1 month ago

After reboot the first attempt sometimes fails, but the 2nd attempt is always ok.

Going to downgrade to .1 and see if it recovers right away

bdraco commented 1 month ago

I does recover right away with .1 so I think the problem is the first request fails after reconnect in .2

joostlek commented 1 month ago

2024-10-04 19:15:28.841 INFO (MainThread) [homeassistant.components.automation.doorbell] Doorbell: Running automation actions
2024-10-04 19:15:28.842 INFO (MainThread) [homeassistant.components.automation.doorbell] Doorbell: Executing step call service
2024-10-04 19:15:28.854 DEBUG (MainThread) [homeassistant.components.cast.media_player] [media_player.kitchen_display Kitchen display] Playing {'media_id': 'http://10.0.0.184:8123/media/local/1_ding_dong.mp3?authSig=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiI1ZGQzNmI2MGRiNzM0OTk0OTg4YThhNDg2MjIxNTJkNSIsInBhdGgiOiIvbWVkaWEvbG9jYWwvMV9kaW5nX2RvbmcubXAzIiwicGFyYW1zIjpbXSwiaWF0IjoxNzI4MDYyMTI4LCJleHAiOjE3MjgxNDg1Mjh9.cY0craOLdMEyphugNWVGtaFFuvgUGNGuobFFEyK3Nz0', 'media_type': 'audio/mpeg'} with default_media_receiver
2024-10-04 19:15:28.855 INFO (SyncWorker_8) [pychromecast.controllers] Receiver:Launching app CC1AD845
2024-10-04 19:15:28.855 DEBUG (SyncWorker_8) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Sending: Message urn:x-cast:com.google.cast.receiver from sender-0 to receiver-0: {'type': 'LAUNCH', 'appId': 'CC1AD845', 'requestId': 30}
2024-10-04 19:15:28.860 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to sender-0: {'launchRequestId': 30, 'status': 'USER_ALLOWED', 'type': 'LAUNCH_STATUS'}
2024-10-04 19:15:28.860 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Message unhandled: Message urn:x-cast:com.google.cast.receiver from receiver-0 to sender-0: {'launchRequestId': 30, 'status': 'USER_ALLOWED', 'type': 'LAUNCH_STATUS'}
2024-10-04 19:15:28.861 INFO (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Heartbeat timeout, resetting connection
2024-10-04 19:15:28.861 INFO (Thread-7) [pychromecast.controllers] Receiver:channel_disconnected
2024-10-04 19:15:28.861 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Sending: Message urn:x-cast:com.google.cast.tp.connection from sender-0 to receiver-0: {'type': 'CLOSE', 'origin': {}}
2024-10-04 19:15:28.862 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] connection listener: 7f5725a300 (CastStatusListener) ConnectionStatus(status='LOST', address=NetworkAddress(address='10.0.0.177', port=8009), service=None)
2024-10-04 19:15:28.862 DEBUG (Thread-7) [homeassistant.components.cast.media_player] [media_player.kitchen_display Kitchen display] Received cast device connection status: LOST
2024-10-04 19:15:28.862 DEBUG (Thread-7) [homeassistant.components.cast.media_player] [media_player.kitchen_display Kitchen display] Cast device availability changed: LOST
2024-10-04 19:15:28.863 DEBUG (Thread-7) [pychromecast.response_handler] Not calling on_success functools.partial(<bound method BaseController.send_message_nocheck of <pychromecast.controllers.media.DefaultMediaReceiverController object at 0x7f6e0f7650>>, {'media': {'contentId': 'http://10.0.0.184:8123/media/local/1_ding_dong.mp3?authSig=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiI1ZGQzNmI2MGRiNzM0OTk0OTg4YThhNDg2MjIxNTJkNSIsInBhdGgiOiIvbWVkaWEvbG9jYWwvMV9kaW5nX2RvbmcubXAzIiwicGFyYW1zIjpbXSwiaWF0IjoxNzI4MDYyMTI4LCJleHAiOjE3MjgxNDg1Mjh9.cY0craOLdMEyphugNWVGtaFFuvgUGNGuobFFEyK3Nz0', 'streamType': 'LIVE', 'contentType': 'audio/mpeg', 'metadata': {}}, 'type': 'LOAD', 'autoplay': True, 'customData': {}}, inc_session_id=True, no_add_request_id=False)
2024-10-04 19:15:28.866 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] connection listener: 7f5725a300 (CastStatusListener) ConnectionStatus(status='CONNECTING', address=NetworkAddress(address='10.0.0.177', port=8009), service=None)
2024-10-04 19:15:28.867 DEBUG (Thread-7) [homeassistant.components.cast.media_player] [media_player.kitchen_display Kitchen display] Received cast device connection status: CONNECTING
2024-10-04 19:15:28.872 ERROR (MainThread) [homeassistant.components.automation.doorbell] Doorbell: Error executing script. Error for call_service at pos 1: CastMediaPlayerEntity._quick_play Failed: Failed to execute quick play http://10.0.0.184:8123/media/local/1_ding_dong.mp3?authSig=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiI1ZGQzNmI2MGRiNzM0OTk0OTg4YThhNDg2MjIxNTJkNSIsInBhdGgiOiIvbWVkaWEvbG9jYWwvMV9kaW5nX2RvbmcubXAzIiwicGFyYW1zIjpbXSwiaWF0IjoxNzI4MDYyMTI4LCJleHAiOjE3MjgxNDg1Mjh9.cY0craOLdMEyphugNWVGtaFFuvgUGNGuobFFEyK3Nz0.
2024-10-04 19:15:28.874 DEBUG (Thread-7) [pychromecast.dial] get_info_from_service resolved service MDNSServiceInfo(name='Google-Nest-Hub-9ee2be5f1b7f6f8324e686a11e38cd0c._googlecast._tcp.local.') to service_info ServiceInfo(type='_googlecast._tcp.local.', name='Google-Nest-Hub-9ee2be5f1b7f6f8324e686a11e38cd0c._googlecast._tcp.local.', addresses=[b'\n\x00\x00\xb1'], port=8009, weight=0, priority=0, server='fuchsia-388b-599d-87eb.local.', properties={b'id': b'9ee2be5f1b7f6f8324e686a11e38cd0c', b'cd': b'4656201CA586D5553484035742A9DF15', b'rm': None, b've': b'05', b'md': b'Google Nest Hub', b'ic': b'/setup/icon.png', b'fn': b'Kitchen display', b'ca': b'231941', b'st': b'0', b'bs': b'FA8FCA7F7607', b'nf': b'1', b'rs': None}, interface_index=None)
2024-10-04 19:15:28.874 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Resolved service MDNSServiceInfo(name='Google-Nest-Hub-9ee2be5f1b7f6f8324e686a11e38cd0c._googlecast._tcp.local.') to 10.0.0.177:8009
2024-10-04 19:15:28.874 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Connecting to 10.0.0.177:8009
2024-10-04 19:15:28.888 ERROR (MainThread) [homeassistant.components.automation.doorbell] Error while executing automation automation.doorbell: CastMediaPlayerEntity._quick_play Failed: Failed to execute quick play http://10.0.0.184:8123/media/local/1_ding_dong.mp3?authSig=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiI1ZGQzNmI2MGRiNzM0OTk0OTg4YThhNDg2MjIxNTJkNSIsInBhdGgiOiIvbWVkaWEvbG9jYWwvMV9kaW5nX2RvbmcubXAzIiwicGFyYW1zIjpbXSwiaWF0IjoxNzI4MDYyMTI4LCJleHAiOjE3MjgxNDg1Mjh9.cY0craOLdMEyphugNWVGtaFFuvgUGNGuobFFEyK3Nz0.
2024-10-04 19:15:28.904 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] connection listener: 7f5725a300 (CastStatusListener) ConnectionStatus(status='CONNECTED', address=NetworkAddress(address='10.0.0.177', port=8009), service=None)
2024-10-04 19:15:28.904 DEBUG (Thread-7) [homeassistant.components.cast.media_player] [media_player.kitchen_display Kitchen display] Received cast device connection status: CONNECTED
2024-10-04 19:15:28.904 DEBUG (Thread-7) [homeassistant.components.cast.media_player] [media_player.kitchen_display Kitchen display] Cast device availability changed: CONNECTED
2024-10-04 19:15:28.904 DEBUG (Thread-7) [homeassistant.components.cast.media_player] [media_player.kitchen_display Kitchen display] Multizone 9975058b-be26-49fa-9f7d-c5d88bf0782a media status: <MediaStatus {'metadata_type': None, 'title': None, 'series_title': None, 'season': None, 'episode': None, 'artist': None, 'album_name': None, 'album_artist': None, 'track': None, 'subtitle_tracks': {}, 'images': [], 'supports_pause': False, 'supports_seek': False, 'supports_stream_volume': False, 'supports_stream_mute': False, 'supports_skip_forward': False, 'supports_skip_backward': False, 'current_time': 0.0, 'content_id': None, 'content_type': None, 'duration': None, 'stream_type': 'UNKNOWN', 'idle_reason': None, 'media_session_id': None, 'playback_rate': 1.0, 'player_state': 'UNKNOWN', 'supported_media_commands': 0, 'volume_level': 1.0, 'volume_muted': False, 'media_custom_data': {}, 'media_metadata': {}, 'current_subtitle_tracks': [], 'last_updated': None}>
2024-10-04 19:15:28.907 DEBUG (Thread-7) [pychromecast.controllers] Receiver:Updating status
2024-10-04 19:15:28.907 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] 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}}
2024-10-04 19:15:28.908 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Sending: Message urn:x-cast:com.google.cast.receiver from sender-0 to receiver-0: {'type': 'GET_STATUS', 'requestId': 1}
2024-10-04 19:15:28.909 INFO (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Connection reestablished!
2024-10-04 19:15:28.930 DEBUG (zeroconf-ServiceBrowser-_googlecast._tcp-153) [pychromecast.discovery] remove_service _googlecast._tcp.local., Google-Nest-Hub-9ee2be5f1b7f6f8324e686a11e38cd0c._googlecast._tcp.local.
2024-10-04 19:15:28.931 DEBUG (zeroconf-ServiceBrowser-_googlecast._tcp-153) [homeassistant.components.cast.discovery] Discovered new or updated chromecast ChromecastInfo(cast_info=CastInfo(services={HostServiceInfo(host='10.0.0.177', port=8009)}, uuid=UUID('9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c'), model_name='Google Nest Hub', friendly_name='Kitchen display', host='10.0.0.177', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2024-10-04 19:15:28.932 DEBUG (MainThread) [homeassistant.components.cast.media_player] _async_create_cast_device: ChromecastInfo(cast_info=CastInfo(services={HostServiceInfo(host='10.0.0.177', port=8009)}, uuid=UUID('9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c'), model_name='Google Nest Hub', friendly_name='Kitchen display', host='10.0.0.177', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2024-10-04 19:15:28.933 DEBUG (MainThread) [homeassistant.components.cast.media_player] Discovered chromecast with same UUID: ChromecastInfo(cast_info=CastInfo(services={HostServiceInfo(host='10.0.0.177', port=8009)}, uuid=UUID('9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c'), model_name='Google Nest Hub', friendly_name='Kitchen display', host='10.0.0.177', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2024-10-04 19:15:28.939 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to sender-0: {'requestId': 1, '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.6000000238418579, 'muted': False, 'stepInterval': 0.019999999552965164}}, 'type': 'RECEIVER_STATUS'}
2024-10-04 19:15:28.939 DEBUG (Thread-7) [pychromecast.controllers] Received status: CastStatus(is_active_input=False, is_stand_by=True, volume_level=0.6000000238418579, volume_muted=False, app_id=None, display_name=None, namespaces=[], session_id=None, transport_id=None, status_text='', icon_url=None, volume_control_type='master')
2024-10-04 19:15:29.770 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to *: {'requestId': 30, 'status': {'applications': [{'appId': 'CC1AD845', 'appType': 'WEB', 'displayName': 'Default Media Receiver', 'iconUrl': '', 'isIdleScreen': False, '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.media'}], 'senderConnected': False, 'sessionId': '87901276-6fbd-4c22-96de-184938cd9dde', 'statusText': 'Default Media Receiver', 'transportId': '87901276-6fbd-4c22-96de-184938cd9dde', 'universalAppId': 'CC1AD845'}], '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.6000000238418579, 'muted': False, 'stepInterval': 0.019999999552965164}}, 'type': 'RECEIVER_STATUS'}
2024-10-04 19:15:29.770 DEBUG (Thread-7) [pychromecast.controllers] Received status: CastStatus(is_active_input=False, is_stand_by=True, volume_level=0.6000000238418579, volume_muted=False, app_id='CC1AD845', display_name='Default Media Receiver', namespaces=['urn:x-cast:com.google.cast.debugoverlay', 'urn:x-cast:com.google.cast.cac', 'urn:x-cast:com.google.cast.media'], session_id='87901276-6fbd-4c22-96de-184938cd9dde', transport_id='87901276-6fbd-4c22-96de-184938cd9dde', status_text='Default Media Receiver', icon_url='', volume_control_type='master')
2024-10-04 19:15:29.771 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Sending: Message urn:x-cast:com.google.cast.tp.connection from sender-0 to 87901276-6fbd-4c22-96de-184938cd9dde: {'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}}
2024-10-04 19:15:29.773 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Sending: Message urn:x-cast:com.google.cast.media from sender-0 to 87901276-6fbd-4c22-96de-184938cd9dde: {'type': 'GET_STATUS', 'requestId': 3}
2024-10-04 19:15:29.791 DEBUG (zeroconf-ServiceBrowser-_googlecast._tcp-153) [pychromecast.discovery] add_service _googlecast._tcp.local., Google-Nest-Hub-9ee2be5f1b7f6f8324e686a11e38cd0c._googlecast._tcp.local.
2024-10-04 19:15:29.797 DEBUG (zeroconf-ServiceBrowser-_googlecast._tcp-153) [homeassistant.components.cast.discovery] Discovered new or updated chromecast ChromecastInfo(cast_info=CastInfo(services={MDNSServiceInfo(name='Google-Nest-Hub-9ee2be5f1b7f6f8324e686a11e38cd0c._googlecast._tcp.local.'), HostServiceInfo(host='10.0.0.177', port=8009)}, uuid=UUID('9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c'), model_name='Google Nest Hub', friendly_name='Kitchen display', host='10.0.0.177', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2024-10-04 19:15:29.799 DEBUG (MainThread) [homeassistant.components.cast.media_player] _async_create_cast_device: ChromecastInfo(cast_info=CastInfo(services={MDNSServiceInfo(name='Google-Nest-Hub-9ee2be5f1b7f6f8324e686a11e38cd0c._googlecast._tcp.local.'), HostServiceInfo(host='10.0.0.177', port=8009)}, uuid=UUID('9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c'), model_name='Google Nest Hub', friendly_name='Kitchen display', host='10.0.0.177', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2024-10-04 19:15:29.799 DEBUG (MainThread) [homeassistant.components.cast.media_player] Discovered chromecast with same UUID: ChromecastInfo(cast_info=CastInfo(services={MDNSServiceInfo(name='Google-Nest-Hub-9ee2be5f1b7f6f8324e686a11e38cd0c._googlecast._tcp.local.'), HostServiceInfo(host='10.0.0.177', port=8009)}, uuid=UUID('9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c'), model_name='Google Nest Hub', friendly_name='Kitchen display', host='10.0.0.177', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2024-10-04 19:15:29.833 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to *: {'requestId': 0, 'status': {'applications': [{'appId': 'CC1AD845', 'appType': 'WEB', 'displayName': 'Default Media Receiver', 'iconUrl': '', 'isIdleScreen': False, '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.media'}], 'senderConnected': True, 'sessionId': '87901276-6fbd-4c22-96de-184938cd9dde', 'statusText': 'Default Media Receiver', 'transportId': '87901276-6fbd-4c22-96de-184938cd9dde', 'universalAppId': 'CC1AD845'}], '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.6000000238418579, 'muted': False, 'stepInterval': 0.019999999552965164}}, 'type': 'RECEIVER_STATUS'}
2024-10-04 19:15:29.833 DEBUG (Thread-7) [pychromecast.controllers] Received status: CastStatus(is_active_input=False, is_stand_by=True, volume_level=0.6000000238418579, volume_muted=False, app_id='CC1AD845', display_name='Default Media Receiver', namespaces=['urn:x-cast:com.google.cast.debugoverlay', 'urn:x-cast:com.google.cast.cac', 'urn:x-cast:com.google.cast.media'], session_id='87901276-6fbd-4c22-96de-184938cd9dde', transport_id='87901276-6fbd-4c22-96de-184938cd9dde', status_text='Default Media Receiver', icon_url='', volume_control_type='master')
2024-10-04 19:15:29.844 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to *: {'requestId': 0, 'status': {'applications': [{'appId': 'CC1AD845', 'appType': 'WEB', 'displayName': 'Default Media Receiver', 'iconUrl': '', 'isIdleScreen': False, '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.media'}], 'senderConnected': True, 'sessionId': '87901276-6fbd-4c22-96de-184938cd9dde', 'statusText': 'Default Media Receiver', 'transportId': '87901276-6fbd-4c22-96de-184938cd9dde', 'universalAppId': 'CC1AD845'}], '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.6000000238418579, 'muted': False, 'stepInterval': 0.019999999552965164}}, 'type': 'RECEIVER_STATUS'}
2024-10-04 19:15:29.845 DEBUG (Thread-7) [pychromecast.controllers] Received status: CastStatus(is_active_input=False, is_stand_by=True, volume_level=0.6000000238418579, volume_muted=False, app_id='CC1AD845', display_name='Default Media Receiver', namespaces=['urn:x-cast:com.google.cast.debugoverlay', 'urn:x-cast:com.google.cast.cac', 'urn:x-cast:com.google.cast.media'], session_id='87901276-6fbd-4c22-96de-184938cd9dde', transport_id='87901276-6fbd-4c22-96de-184938cd9dde', status_text='Default Media Receiver', icon_url='', volume_control_type='master')
2024-10-04 19:15:30.324 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Received: Message urn:x-cast:com.google.cast.media from 87901276-6fbd-4c22-96de-184938cd9dde to *: {'type': 'MEDIA_STATUS', 'status': [], 'requestId': 0}
2024-10-04 19:15:30.324 DEBUG (Thread-7) [pychromecast.controllers] Media:Updated status <MediaStatus {'metadata_type': None, 'title': None, 'series_title': None, 'season': None, 'episode': None, 'artist': None, 'album_name': None, 'album_artist': None, 'track': None, 'subtitle_tracks': {}, 'images': [], 'supports_pause': False, 'supports_seek': False, 'supports_stream_volume': False, 'supports_stream_mute': False, 'supports_skip_forward': False, 'supports_skip_backward': False, 'current_time': 0.0, 'content_id': None, 'content_type': None, 'duration': None, 'stream_type': 'UNKNOWN', 'idle_reason': None, 'media_session_id': None, 'playback_rate': 1.0, 'player_state': 'UNKNOWN', 'supported_media_commands': 0, 'volume_level': 1.0, 'volume_muted': False, 'media_custom_data': {}, 'media_metadata': {}, 'current_subtitle_tracks': [], 'last_updated': None}>
2024-10-04 19:15:30.404 DEBUG (Thread-7) [pychromecast.socket_client] [Kitchen display(10.0.0.177):8009] Received: Message urn:x-cast:com.google.cast.media from 87901276-6fbd-4c22-96de-184938cd9dde to sender-0: {'type': 'MEDIA_STATUS', 'status': [], 'requestId': 3}
2024-10-04 19:15:30.404 DEBUG (Thread-7) [pychromecast.controllers] Media:Updated status <MediaStatus {'metadata_type': None, 'title': None, 'series_title': None, 'season': None, 'episode': None, 'artist': None, 'album_name': None, 'album_artist': None, 'track': None, 'subtitle_tracks': {}, 'images': [], 'supports_pause': False, 'supports_seek': False, 'supports_stream_volume': False, 'supports_stream_mute': False, 'supports_skip_forward': False, 'supports_skip_backward': False, 'current_time': 0.0, 'content_id': None, 'content_type': None, 'duration': None, 'stream_type': 'UNKNOWN', 'idle_reason': None, 'media_session_id': None, 'playback_rate': 1.0, 'player_state': 'UNKNOWN', 'supported_media_commands': 0, 'volume_level': 1.0, 'volume_muted': False, 'media_custom_data': {}, 'media_metadata': {}, 'current_subtitle_tracks': [], 'last_updated': None}>
2024-10-04 19:15:33.379 INFO (SyncWorker_2) [pylast] user.getInfo
2024-10-04 19:15:33.916 INFO (SyncWorker_2) [pylast] user.getInfo
2024-10-04 19:15:34.787 INFO (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] Heartbeat timeout, resetting connection
2024-10-04 19:15:34.787 INFO (Thread-6) [pychromecast.controllers] Receiver:channel_disconnected
2024-10-04 19:15:34.788 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] Sending: Message urn:x-cast:com.google.cast.tp.connection from sender-0 to receiver-0: {'type': 'CLOSE', 'origin': {}}
2024-10-04 19:15:34.789 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] connection listener: 7f5723deb0 (Listener) ConnectionStatus(status='LOST', address=NetworkAddress(address='10.0.0.177', port=32197), service=None)
2024-10-04 19:15:34.789 DEBUG (Thread-6) [pychromecast.controllers.multizone] (9975058b-be26-49fa-9f7d-c5d88bf0782a) Removed member 9b6a829f-1a1c-2466-0ffe-7db5353e5188(Chromecast), members: {'9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c': 'Kitchen display'}
2024-10-04 19:15:34.789 DEBUG (Thread-6) [homeassistant.components.cast.media_player] [media_player.tv Chromecast] Multizone 9975058b-be26-49fa-9f7d-c5d88bf0782a media status: None
2024-10-04 19:15:34.790 DEBUG (Thread-6) [pychromecast.controllers.multizone] (9975058b-be26-49fa-9f7d-c5d88bf0782a) Removed member 9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c(Kitchen display), members: {}
2024-10-04 19:15:34.790 DEBUG (Thread-6) [homeassistant.components.cast.media_player] [media_player.kitchen_display Kitchen display] Multizone 9975058b-be26-49fa-9f7d-c5d88bf0782a media status: None
2024-10-04 19:15:34.790 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] connection listener: 7f57195550 (CastStatusListener) ConnectionStatus(status='LOST', address=NetworkAddress(address='10.0.0.177', port=32197), service=None)
2024-10-04 19:15:34.790 DEBUG (Thread-6) [homeassistant.components.cast.media_player] [media_player.living_room Living room] Received cast device connection status: LOST
2024-10-04 19:15:34.791 DEBUG (Thread-6) [homeassistant.components.cast.media_player] [media_player.living_room Living room] Cast device availability changed: LOST
2024-10-04 19:15:34.800 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] connection listener: 7f5723deb0 (Listener) ConnectionStatus(status='CONNECTING', address=NetworkAddress(address='10.0.0.177', port=32197), service=None)
2024-10-04 19:15:34.800 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] connection listener: 7f57195550 (CastStatusListener) ConnectionStatus(status='CONNECTING', address=NetworkAddress(address='10.0.0.177', port=32197), service=None)
2024-10-04 19:15:34.800 DEBUG (Thread-6) [homeassistant.components.cast.media_player] [media_player.living_room Living room] Received cast device connection status: CONNECTING
2024-10-04 19:15:34.809 DEBUG (Thread-6) [pychromecast.dial] get_info_from_service resolved service MDNSServiceInfo(name='Google-Cast-Group-9975058bbe2649fa9f7dc5d88bf0782a-1._googlecast._tcp.local.') to service_info ServiceInfo(type='_googlecast._tcp.local.', name='Google-Cast-Group-9975058bbe2649fa9f7dc5d88bf0782a-1._googlecast._tcp.local.', addresses=[b'\n\x00\x00\xb1'], port=32197, weight=0, priority=0, server='fuchsia-388b-599d-87eb.local.', properties={b'id': b'9975058b-be26-49fa-9f7d-c5d88bf0782a', b'cd': b'9975058b-be26-49fa-9f7d-c5d88bf0782a', b'rm': None, b've': b'05', b'md': b'Google Cast Group', b'ic': b'/setup/icon.png', b'fn': b'Living room', b'ca': b'199204', b'st': b'0', b'bs': b'FA8FCA7F7607', b'nf': b'1', b'rs': None}, interface_index=None)
2024-10-04 19:15:34.810 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] Resolved service MDNSServiceInfo(name='Google-Cast-Group-9975058bbe2649fa9f7dc5d88bf0782a-1._googlecast._tcp.local.') to 10.0.0.177:32197
2024-10-04 19:15:34.810 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] Connecting to 10.0.0.177:32197
2024-10-04 19:15:34.840 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] connection listener: 7f5723deb0 (Listener) ConnectionStatus(status='CONNECTED', address=NetworkAddress(address='10.0.0.177', port=32197), service=None)
2024-10-04 19:15:34.840 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] 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}}
2024-10-04 19:15:34.841 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] Sending: Message urn:x-cast:com.google.cast.multizone from sender-0 to receiver-0: {'type': 'GET_STATUS', 'requestId': 1}
2024-10-04 19:15:34.842 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] connection listener: 7f57195550 (CastStatusListener) ConnectionStatus(status='CONNECTED', address=NetworkAddress(address='10.0.0.177', port=32197), service=None)
2024-10-04 19:15:34.843 DEBUG (Thread-6) [homeassistant.components.cast.media_player] [media_player.living_room Living room] Received cast device connection status: CONNECTED
2024-10-04 19:15:34.843 DEBUG (Thread-6) [homeassistant.components.cast.media_player] [media_player.living_room Living room] Cast device availability changed: CONNECTED
2024-10-04 19:15:34.843 DEBUG (Thread-6) [pychromecast.controllers] Receiver:Updating status
2024-10-04 19:15:34.844 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] Sending: Message urn:x-cast:com.google.cast.receiver from sender-0 to receiver-0: {'type': 'GET_STATUS', 'requestId': 2}
2024-10-04 19:15:34.845 INFO (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] Connection reestablished!
2024-10-04 19:15:34.855 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] Received: Message urn:x-cast:com.google.cast.multizone from receiver-0 to sender-0: {'requestId': 1, 'status': {'devices': [{'capabilities': 229381, 'deviceId': '9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c', 'name': 'Kitchen display', 'volume': {'level': 0.6000000238418579, 'muted': False}}, {'capabilities': 196613, 'deviceId': '9b6a829f-1a1c-2466-0ffe-7db5353e5188', 'name': 'Chromecast', 'volume': {'level': 0.8000000715255737, 'muted': False}}], 'isMultichannel': False}, 'type': 'MULTIZONE_STATUS'}
2024-10-04 19:15:34.855 DEBUG (Thread-6) [pychromecast.controllers.multizone] (9975058b-be26-49fa-9f7d-c5d88bf0782a) Added members ['9b6a829f-1a1c-2466-0ffe-7db5353e5188', '9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c'], Removed members: []
2024-10-04 19:15:34.855 DEBUG (Thread-6) [pychromecast.controllers.multizone] (9975058b-be26-49fa-9f7d-c5d88bf0782a) Added member 9b6a829f-1a1c-2466-0ffe-7db5353e5188(Chromecast), members: {'9b6a829f-1a1c-2466-0ffe-7db5353e5188': 'Chromecast'}
2024-10-04 19:15:34.855 DEBUG (Thread-6) [pychromecast.controllers.multizone] (9975058b-be26-49fa-9f7d-c5d88bf0782a) Added member 9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c(Kitchen display), members: {'9b6a829f-1a1c-2466-0ffe-7db5353e5188': 'Chromecast', '9ee2be5f-1b7f-6f83-24e6-86a11e38cd0c': 'Kitchen display'}
2024-10-04 19:15:34.857 DEBUG (Thread-6) [pychromecast.socket_client] [Living room(10.0.0.177):32197] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to sender-0: {'requestId': 2, '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.7000000476837158, 'muted': False, 'stepInterval': 0.05000000074505806}}, 'type': 'RECEIVER_STATUS'}
2024-10-04 19:15:34.857 DEBUG (Thread-6) [pychromecast.controllers] Received status: CastStatus(is_active_input=None, is_stand_by=None, volume_level=0.7000000476837158, volume_muted=False, app_id=None, display_name=None, namespaces=[], session_id=None, transport_id=None, status_text='', icon_url=None, volume_control_type='master')

bdraco commented 1 month ago

It looks like we don't wait for the reconnect on failure anymore or there is another race

2024-10-04 12:16:28.386 DEBUG (zeroconf-ServiceBrowser-_googlecast._tcp-274556) [pychromecast.discovery] add_service _googlecast._tcp.local., Chromecast-59d931dd8cf7b8e75b0572e58acfdfda._googlecast._tcp.local.
2024-10-04 12:16:28.611 INFO (SyncWorker_2) [pychromecast.controllers] Receiver:Launching app CC1AD845
2024-10-04 12:16:28.612 DEBUG (SyncWorker_2) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] Sending: Message urn:x-cast:com.google.cast.receiver from sender-0 to receiver-0: {'type': 'LAUNCH', 'appId': 'CC1AD845', 'requestId': 7}
2024-10-04 12:16:28.625 ERROR (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] Error reading from socket: socket connection broken
2024-10-04 12:16:28.625 DEBUG (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] Forced reconnection
2024-10-04 12:16:28.625 INFO (Thread-4) [pychromecast.controllers] Receiver:channel_disconnected
2024-10-04 12:16:28.625 DEBUG (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] Sending: Message urn:x-cast:com.google.cast.tp.connection from sender-0 to receiver-0: {'type': 'CLOSE', 'origin': {}}
2024-10-04 12:16:28.625 DEBUG (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] connection listener: 34ae398e0 (CastStatusListener) ConnectionStatus(status='LOST', address=NetworkAddress(address='192.168.211.207', port=8009), service=None)
2024-10-04 12:16:28.627 DEBUG (Thread-4) [pychromecast.response_handler] Not calling on_success functools.partial(<bound method BaseController.send_message_nocheck of <pychromecast.controllers.media.DefaultMediaReceiverController object at 0x35c265790>>, {'media': {'contentId': 'https://file-examples.com/storage/fe36b23e6a66fc0679c1f86/2017/11/file_example_MP3_2MG.mp3', 'streamType': 'LIVE', 'contentType': 'music', 'metadata': {}}, 'type': 'LOAD', 'autoplay': True, 'customData': {}}, inc_session_id=True, no_add_request_id=False)
2024-10-04 12:16:28.628 DEBUG (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] connection listener: 34ae398e0 (CastStatusListener) ConnectionStatus(status='CONNECTING', address=NetworkAddress(address='192.168.211.207', port=8009), service=None)
2024-10-04 12:16:28.628 DEBUG (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] Resolved service HostServiceInfo(host='192.168.211.207', port=8009) to 192.168.211.207:8009
2024-10-04 12:16:28.629 DEBUG (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] Connecting to 192.168.211.207:8009
2024-10-04 12:16:28.629 ERROR (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Error executing script. Error for call_service at pos 1: CastMediaPlayerEntity._quick_play Failed: Failed to execute quick play https://file-examples.com/storage/fe36b23e6a66fc0679c1f86/2017/11/file_example_MP3_2MG.mp3.
2024-10-04 12:16:28.630 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [14215510144] Error handling message: CastMediaPlayerEntity._quick_play Failed: Failed to execute quick play https://file-examples.com/storage/fe36b23e6a66fc0679c1f86/2017/11/file_example_MP3_2MG.mp3. (home_assistant_error) J. Nick Koston from 127.0.0.1 (Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36)
2024-10-04 12:16:28.662 DEBUG (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] connection listener: 34ae398e0 (CastStatusListener) ConnectionStatus(status='CONNECTED', address=NetworkAddress(address='192.168.211.207', port=8009), service=None)
2024-10-04 12:16:28.663 DEBUG (Thread-4) [pychromecast.controllers] Receiver:Updating status
2024-10-04 12:16:28.663 DEBUG (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] 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}}
2024-10-04 12:16:28.664 DEBUG (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] Sending: Message urn:x-cast:com.google.cast.receiver from sender-0 to receiver-0: {'type': 'GET_STATUS', 'requestId': 1}
2024-10-04 12:16:28.664 INFO (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] Connection reestablished!
2024-10-04 12:16:28.712 DEBUG (Thread-4) [pychromecast.socket_client] [Living Room TV(192.168.211.207):8009] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to sender-0: {'requestId': 1, 'status': {'applications': [{'appId': 'E8C28D3C', 'appType': 'WEB', 'displayName': 'Backdrop', 'iconUrl': '', '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': 'e98281ec-7c5d-47a8-95d9-81ca1895de48', 'statusText': '', 'transportId': 'e98281ec-7c5d-47a8-95d9-81ca1895de48', 'universalAppId': 'E8C28D3C'}], 'userEq': {}, 'volume': {'controlType': 'attenuation', 'level': 0.9891123175621033, 'muted': False, 'stepInterval': 0.05000000074505806}}, 'type': 'RECEIVER_STATUS'}
2024-10-04 12:16:28.712 DEBUG (Thread-4) [pychromecast.controllers] Received status: CastStatus(is_active_input=False, is_stand_by=True, volume_level=0.9891123175621033, 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='e98281ec-7c5d-47a8-95d9-81ca1895de48', transport_id='e98281ec-7c5d-47a8-95d9-81ca1895de48', status_text='', icon_url='', volume_control_type='attenuation')

bdraco commented 1 month ago

I was thinking the problem might have been https://github.com/home-assistant-libs/pychromecast/pull/865 but I went back a commit before that and it still has the issue where it doesn't work the first time after reboot

bdraco commented 1 month ago

going to try reverting #883 and seeing if that fixes it

bdraco commented 1 month ago

reverting #883 fixed the not reconnect after reboot problem

bdraco commented 1 month ago

testing with #965

bdraco commented 1 month ago

That fixed it for me

emontnemery commented 1 month ago

Let's keep this open until the issue is understood

emontnemery commented 1 month ago

The root cause is that when the socket read does not time out after merge of #877, we don't call the HeartbeatController often enough.

A correct version of #877 is in https://github.com/home-assistant-libs/pychromecast/pull/967

home-assistant-libs / pychromecast

14.0.2 sometimes fails to play media in Home Assistant #964