search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
71.91k stars 30.13k forks source link

Songpal has issues starting up #119662

Closed clowncracker closed 1 month ago

clowncracker commented 3 months ago

The problem

Whenever I start Home Assistant, Songpal seems to have issues starting. I see the following warnings in my log:

Logger: homeassistant.components.media_player
Source: runner.py:190
integration: Media player
First occurred: 8:45:49 PM (1 occurrences)
Last logged: 8:45:49 PM
Setup of media_player platform songpal is taking over 10 seconds.

Logger: homeassistant.components.songpal.media_player
Source: components/songpal/media_player.py:79
integration: Sony Songpal (documentation, issues)
First occurred: 8:45:49 PM (1 occurrences)
Last logged: 8:45:49 PM
[HT-A7000(http://192.168.20.42:10000/sony)] Unable to connect

Logger: homeassistant.components.media_player
Source: helpers/entity_platform.py:381
integration: Media player (documentation, issues)
First occurred: 8:45:49 PM (1 occurrences)
Last logged: 8:45:49 PM

Platform songpal not ready yet; Retrying in background in 30 seconds

What version of Home Assistant Core has the issue?

core-2024.6.2

What was the last working version of Home Assistant Core?

core-2024.5.5

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Songpal

Link to integration documentation on our website

https://www.home-assistant.io/integrations/songpal/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logger: homeassistant.components.media_player
Source: runner.py:190
integration: Media player
First occurred: 8:45:49 PM (1 occurrences)
Last logged: 8:45:49 PM
Setup of media_player platform songpal is taking over 10 seconds.

Logger: homeassistant.components.songpal.media_player
Source: components/songpal/media_player.py:79
integration: Sony Songpal (documentation, issues)
First occurred: 8:45:49 PM (1 occurrences)
Last logged: 8:45:49 PM
[HT-A7000(http://192.168.20.42:10000/sony)] Unable to connect

Logger: homeassistant.components.media_player
Source: helpers/entity_platform.py:381
integration: Media player (documentation, issues)
First occurred: 8:45:49 PM (1 occurrences)
Last logged: 8:45:49 PM

Platform songpal not ready yet; Retrying in background in 30 seconds


### Additional information

This has only started happening in 2024.6.x, I didn't have this issue in any prior release.
home-assistant[bot] commented 3 months ago

Hey there @rytilahti, @shenxn, mind taking a look at this issue as it has been labeled with an integration (songpal) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `songpal` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign songpal` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)

songpal documentation songpal source (message by IssueLinks)

rytilahti commented 3 months ago

If you downgrade to .5, does it start to work again? I'm wondering if it could be related to some earlier changes, perhaps related to #119626?

You could also enable debug logging to get some more information from the songpal integration as those log entries do not give any details why the connection is breaking down.

clowncracker commented 3 months ago

If you downgrade to .5, does it start to work again? I'm wondering if it could be related to some earlier changes, perhaps related to #119626?

You could also enable debug logging to get some more information from the songpal integration as those log entries do not give any details why the connection is breaking down.

I don't have a good way to access my .5 version anymore, but here are the startup debug logs:

2024-06-14 08:44:58.630 DEBUG (MainThread) [songpal.device] Endpoint: http://192.168.20.42:10000/sony
2024-06-14 08:44:58.630 DEBUG (MainThread) [songpal.device] Guide endpoint: http://192.168.20.42:10000/sony/guide
2024-06-14 08:44:58.757 DEBUG (MainThread) [songpal.device] Got 5 services!
2024-06-14 08:44:58.757 DEBUG (MainThread) [songpal.service] Available protocols for appControl: ['xhrpost:jsonizer', 'websocket:jsonizer']
2024-06-14 08:44:58.757 DEBUG (MainThread) [songpal.service] Using protocol: ProtocolType.WebSocket
2024-06-14 08:44:58.853 DEBUG (MainThread) [songpal.service] Available protocols for audio: ['xhrpost:jsonizer', 'websocket:jsonizer']
2024-06-14 08:44:58.854 DEBUG (MainThread) [songpal.service] Using protocol: ProtocolType.WebSocket
2024-06-14 08:44:59.074 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyVolumeInformation', 'versions': [{'version': '1.0'}]}
2024-06-14 08:44:59.074 DEBUG (MainThread) [songpal.service] Got notifications: [<Notification notifyVolumeInformation, versions=[{'version': '1.0'}], endpoint=http://192.168.20.42:10000/sony/audio>]
2024-06-14 08:44:59.074 DEBUG (MainThread) [songpal.service] Available protocols for avContent: ['xhrpost:jsonizer', 'websocket:jsonizer']
2024-06-14 08:44:59.074 DEBUG (MainThread) [songpal.service] Using protocol: ProtocolType.WebSocket
2024-06-14 08:44:59.152 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyAvailablePlaybackFunction', 'versions': [{'version': '1.0'}]}
2024-06-14 08:44:59.152 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyPlayingContentInfo',
 'versions': [{'authLevel': 'private', 'version': '1.0'}]}
2024-06-14 08:44:59.152 DEBUG (MainThread) [songpal.service] Got notifications: [<Notification notifyAvailablePlaybackFunction, versions=[{'version': '1.0'}], endpoint=http://192.168.20.42:10000/sony/avContent>, <Notification notifyPlayingContentInfo, versions=[{'authLevel': 'private', 'version': '1.0'}], endpoint=http://192.168.20.42:10000/sony/avContent>]
2024-06-14 08:44:59.152 DEBUG (MainThread) [songpal.service] Available protocols for guide: ['websocket:jsonizer']
2024-06-14 08:44:59.152 DEBUG (MainThread) [songpal.service] Using protocol: ProtocolType.WebSocket
2024-06-14 08:44:59.247 DEBUG (MainThread) [songpal.service] Available protocols for system: ['xhrpost:jsonizer', 'websocket:jsonizer']
2024-06-14 08:44:59.248 DEBUG (MainThread) [songpal.service] Using protocol: ProtocolType.WebSocket
2024-06-14 08:44:59.321 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyAlexaRegistrationStatus',
 'versions': [{'authLevel': 'none', 'version': '1.0'}]}
2024-06-14 08:44:59.321 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyPowerStatus',
 'versions': [{'authLevel': 'none', 'version': '1.0'}]}
2024-06-14 08:44:59.321 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifySettingsUpdate',
 'versions': [{'authLevel': 'none', 'version': '1.1'}]}
2024-06-14 08:44:59.321 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyStorageStatus',
 'versions': [{'authLevel': 'generic', 'version': '1.1'}]}
2024-06-14 08:44:59.321 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifySWUpdateInfo',
 'versions': [{'authLevel': 'none', 'version': '1.0'}]}
2024-06-14 08:44:59.321 DEBUG (MainThread) [songpal.service] Got notifications: [<Notification notifyAlexaRegistrationStatus, versions=[{'authLevel': 'none', 'version': '1.0'}], endpoint=http://192.168.20.42:10000/sony/system>, <Notification notifyPowerStatus, versions=[{'authLevel': 'none', 'version': '1.0'}], endpoint=http://192.168.20.42:10000/sony/system>, <Notification notifySettingsUpdate, versions=[{'authLevel': 'none', 'version': '1.1'}], endpoint=http://192.168.20.42:10000/sony/system>, <Notification notifyStorageStatus, versions=[{'authLevel': 'generic', 'version': '1.1'}], endpoint=http://192.168.20.42:10000/sony/system>, <Notification notifySWUpdateInfo, versions=[{'authLevel': 'none', 'version': '1.0'}], endpoint=http://192.168.20.42:10000/sony/system>]
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for appControl.getMethodTypes, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for appControl.getVersions, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for audio.getCustomEqualizerSettings, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for audio.getMethodTypes, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for audio.getVersions, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for audio.setCustomEqualizerSettings, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.getMethodTypes, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.getVersions, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.presetBroadcastStation, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.seekBroadcastStation, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.setActiveTerminal, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.startContentBrowsing, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.getContentCount, using 1.3
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.getContentList, using 1.4
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for guide.getMethodTypes, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for guide.getVersions, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for guide.switchNotifications, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for system.getMethodTypes, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.device] No supported version specified for system.getVersions, using 1.0
2024-06-14 08:44:59.322 DEBUG (MainThread) [songpal.service] getSystemInformation version 1.4 got called with args (()) kwargs ({})
2024-06-14 08:44:59.476 DEBUG (MainThread) [songpal.containers] Missing key bssid with no default for Sysinfo
2024-06-14 08:44:59.476 DEBUG (MainThread) [songpal.containers] Missing key ssid with no default for Sysinfo
2024-06-14 08:44:59.476 DEBUG (MainThread) [songpal.service] getInterfaceInformation version 1.0 got called with args (()) kwargs ({})
2024-06-14 08:44:59.613 DEBUG (MainThread) [songpal.service] getVolumeInformation version 1.1 got called with args (({},)) kwargs ({})
2024-06-14 08:45:15.362 DEBUG (MainThread) [songpal.containers] Missing key output with no default for Volume
2024-06-14 08:45:15.362 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Current volume: Volume: 34/100
2024-06-14 08:45:15.362 DEBUG (MainThread) [songpal.service] getPowerStatus version 1.1 got called with args (()) kwargs ({})
2024-06-14 08:45:15.436 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Got state: Power off
2024-06-14 08:45:15.436 DEBUG (MainThread) [songpal.service] getCurrentExternalTerminalsStatus version 1.0 got called with args (()) kwargs ({})
2024-06-14 08:45:15.505 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Got ins: [Input(meta='meta:tv', connection='connected', title='TV', uri='extInput:tv', active=True, label='', iconUrl='', outputs=[]), Input(meta='meta:hdmi', connection='connected', title='HDMI1', uri='extInput:hdmi?port=1', active=True, label='', iconUrl='', outputs=[]), Input(meta='meta:hdmi', connection='connected', title='HDMI2', uri='extInput:hdmi?port=2', active=True, label='', iconUrl='', outputs=[]), Input(meta='meta:linemini', connection='connected', title='Analog', uri='extInput:line', active=True, label='', iconUrl='', outputs=[]), Input(meta='meta:btaudio', connection='connected', title='Bluetooth Audio', uri='extInput:btAudio', active=True, label='', iconUrl='', outputs=[])]
2024-06-14 08:45:15.505 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Active source: Bluetooth Audio (uri: extInput:btAudio) (active)
2024-06-14 08:45:15.506 DEBUG (MainThread) [songpal.service] getSoundSettings version 1.1 got called with args (({'target': 'soundField'},)) kwargs ({})
2024-06-14 08:45:15.579 DEBUG (MainThread) [songpal.containers] Missing key deviceUIInfo with no default for Setting
2024-06-14 08:45:15.579 DEBUG (MainThread) [songpal.containers] Missing key uri with no default for Setting
2024-06-14 08:45:15.579 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Got sound modes: {'auto': SettingCandidate(title='Auto Sound', value='auto', isAvailable=True, min=-1, max=-1, step=-1, titleTextID='sound-soundfield-soundauto'), 'cinemaStudio': SettingCandidate(title='Cinema', value='cinemaStudio', isAvailable=True, min=-1, max=-1, step=-1, titleTextID='sound-soundfield-cinema'), 'music': SettingCandidate(title='Music', value='music', isAvailable=True, min=-1, max=-1, step=-1, titleTextID='sound-soundfield-music-2'), 'standard': SettingCandidate(title='Standard Surround', value='standard', isAvailable=True, min=-1, max=-1, step=-1, titleTextID='sound-soundfield-standard-2')}
2024-06-14 08:45:15.579 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Active sound mode: cinemaStudio
2024-06-14 08:45:15.580 INFO (MainThread) [homeassistant.components.songpal.media_player] Activating websocket connection
2024-06-14 08:45:15.580 DEBUG (MainThread) [songpal.service] No notifications available for appControl
2024-06-14 08:45:15.580 DEBUG (MainThread) [songpal.service] switchNotifications version 1.0 got called with args (({'enabled': [{'name': 'notifyVolumeInformation', 'version': '1.0'}]},)) kwargs ({'_consumer': <function Device.listen_notifications.<locals>.handle_notification at 0x7fc2e025b560>})
2024-06-14 08:45:15.581 DEBUG (MainThread) [songpal.service] switchNotifications version 1.0 got called with args (({'enabled': [{'name': 'notifyAvailablePlaybackFunction', 'version': '1.0'}, {'name': 'notifyPlayingContentInfo', 'version': '1.0'}]},)) kwargs ({'_consumer': <function Device.listen_notifications.<locals>.handle_notification at 0x7fc2e025b560>})
2024-06-14 08:45:15.582 DEBUG (MainThread) [songpal.service] No notifications available for guide
2024-06-14 08:45:15.582 DEBUG (MainThread) [songpal.service] switchNotifications version 1.0 got called with args (({'enabled': [{'name': 'notifyAlexaRegistrationStatus', 'version': '1.0'}, {'name': 'notifyPowerStatus', 'version': '1.0'}, {'name': 'notifySettingsUpdate', 'version': '1.1'}, {'name': 'notifyStorageStatus', 'version': '1.1'}, {'name': 'notifySWUpdateInfo', 'version': '1.0'}]},)) kwargs ({'_consumer': <function Device.listen_notifications.<locals>.handle_notification at 0x7fc2e025b560>})
2024-06-14 08:45:15.671 DEBUG (MainThread) [songpal.service] Got notification: <NotificationChange enabled: notifyVolumeInformation disabled: >
2024-06-14 08:45:15.672 DEBUG (MainThread) [songpal.device] No callbacks defined for <NotificationChange enabled: notifyVolumeInformation disabled: >
2024-06-14 08:45:15.672 DEBUG (MainThread) [songpal.service] Got notification: <NotificationChange enabled: notifyAvailablePlaybackFunction,notifyPlayingContentInfo disabled: notifyExternalTerminalStatus>
2024-06-14 08:45:15.672 DEBUG (MainThread) [songpal.device] No callbacks defined for <NotificationChange enabled: notifyAvailablePlaybackFunction,notifyPlayingContentInfo disabled: notifyExternalTerminalStatus>
2024-06-14 08:45:15.689 DEBUG (MainThread) [songpal.service] Got notification: <NotificationChange enabled: notifyAlexaRegistrationStatus,notifyPowerStatus,notifySWUpdateInfo,notifySettingsUpdate,notifyStorageStatus disabled: >
2024-06-14 08:45:15.689 DEBUG (MainThread) [songpal.device] No callbacks defined for <NotificationChange enabled: notifyAlexaRegistrationStatus,notifyPowerStatus,notifySWUpdateInfo,notifySettingsUpdate,notifyStorageStatus disabled: >
rytilahti commented 3 months ago

Does it just get stuck there or do you get some warnings or errors later on, when it fails to start?

clowncracker commented 3 months ago

It seems to have problems throughout the day, disconnecting and reconnecting. The description of the issue and related logs are documented here:

https://github.com/rytilahti/python-songpal/issues/156

rytilahti commented 3 months ago

If you know how to run development environment, you could try and see if it's fixed in the current dev branch now that https://github.com/home-assistant/core/pull/119999 is merged :-)