Skip to content
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

Sony Songpal becomes unavailable/available every minute #151

Closed
clowncracker opened this issue Mar 14, 2024 · 21 comments
Closed

Sony Songpal becomes unavailable/available every minute #151

clowncracker opened this issue Mar 14, 2024 · 21 comments

Comments

@clowncracker
Copy link

Opening a ticket here per: home-assistant/core#111121.

It looks like the cause of the issue is #145.

@rytilahti
Copy link
Owner

I think here's the relevant piece of information:

2024-02-23 15:11:47.201 WARNING (MainThread) [homeassistant.components.songpal.media_player] [None(http://192.168.20.42:10000/sony)] Got disconnected, trying to reconnect
2024-02-23 15:11:47.201 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Disconnected: Unable to make a request: Received message 257:None is not str: None

@allistermaguire any ideas? :-)

@allistermaguire
Copy link
Contributor

@rytilahti Not a lot to go on in the logs, but I will have a look.

@rytilahti
Copy link
Owner

Thanks 👍 My understanding is that something just breaks the websocket connection. A more complete log is in the linked issue, but I couldn't tell anything that clearly pinpoints what exactly. Maybe be one of the notification subscription, as those are the last lines pre-exception, but it feels odd?

@allistermaguire
Copy link
Contributor

Thanks. Yeah, it is odd, that is my thought as well, there is very little between 0.16.0 and 0.16.1. I am currently investigating #143

@rytilahti
Copy link
Owner

rytilahti commented Mar 16, 2024

That is just about exporting those classes through the main package, so it shouldn't be an issue. My guess would have been some general network issues, but when downgrading fixes it.. 🤷

@clowncracker is it really working consistently on the earlier version, or did you just get lucky / could it be caused by weak wifi signal or something similar?

@clowncracker
Copy link
Author

@rytilahti I don't believe the issue is wifi related. It's been three days since I've downgraded to 0.16.0 and the issue hasn't showed up in my logs once. On 0.16.1 it was happening every minute.

@allistermaguire
Copy link
Contributor

That is just about exporting those classes through the main package, so it shouldn't be an issue. My guess would have been some general network issues, but when downgrading fixes it.. 🤷

I agree, but from the logs, I can see that the conditional logic in #145 isn't entered.

@clowncracker what device do you have? To help to diagnose, can you please run the following commands on your Home Assistant machine?

songpal --version
songpal discover 
songpal --endpoint http:/xxx.xxx.xxx.xxx:10000/sony dump-devinfo   
songpal --endpoint http:/xxx.xxx.xxx.xxx:10000/sony notifications   

@clowncracker
Copy link
Author

That is just about exporting those classes through the main package, so it shouldn't be an issue. My guess would have been some general network issues, but when downgrading fixes it.. 🤷

I agree, but from the logs, I can see that the conditional logic in #145 isn't entered.

@clowncracker what device do you have? To help to diagnose, can you please run the following commands on your Home Assistant machine?

songpal --version
songpal discover 
songpal --endpoint http:/xxx.xxx.xxx.xxx:10000/sony dump-devinfo   
songpal --endpoint http:/xxx.xxx.xxx.xxx:10000/sony notifications   

zsh: command not found: songpal

Does the songpal command not work when changing songpal to a custom component? The device is a HT-A7000.

@allistermaguire
Copy link
Contributor

allistermaguire commented Mar 16, 2024

Hey @clowncracker, it should, as a dependency it will download and install. I have looked at home-assistant/core#111121 to see what you did, and that looks fine. You do have a mismatch of versions; I think you have 2024.2.2 installed, and running songpal from 2024.3.0. But the difference is very small, so should be good.

How do you run Home Assistant? is it installed in a python virtual environment? If the later, you will need to run those commands within the virtual environment.

@clowncracker
Copy link
Author

@allistermaguire I opened the ticket awhile ago, I have 2024.3.1 installed at this point.

I'm running HA in a VM, I opened the terminal window and got the response I mentioned previously.

@allistermaguire
Copy link
Contributor

Thanks @clowncracker, is it Home Assistant Operating System as the VM, or did you install Linux and then HA on top?

I run HA in docker, so I am trying to understand your setup better so I can provide more assistance.

@clowncracker
Copy link
Author

Thanks @clowncracker, is it Home Assistant Operating System as the VM, or did you install Linux and then HA on top?

I run HA in docker, so I am trying to understand your setup better so I can provide more assistance.

I'm running it on an Unraid server as a VM. I cannot use the command through the Advanced SSH & Web Terminal addon or through just opening the terminal through the VM.

@allistermaguire
Copy link
Contributor

allistermaguire commented Mar 16, 2024

Thanks @clowncracker. I don't know much about HA OS, but I have done some reading. As you say that will not work as you are not within the docker container.

You will need to disabled protective mode, you can see instructions here https://github.com/hassio-addons/addon-ssh/blob/main/ssh/rootfs/usr/local/bin/docker

And then it is possible to connect to the container by running the following:

docker exec -it homeassistant /bin/bash

Once connected, songpal should be available.

@allistermaguire
Copy link
Contributor

Hey @clowncracker, have you been able to get the above to work? need some additional data to help diagnose your issue.

@rytilahti
Copy link
Owner

home-assistant/core#114525 bumps the version, so this should work in the upcoming homeassistant 2024.4 again. @clowncracker please reopen this issue, if it isn't working for you. @allistermaguire thanks for the quick fix! 💯

@clowncracker
Copy link
Author

@rytilahti not sure if I should open a new ticket, but this has started happening again. It gets disconnected in random intervals and it reconnects again after 11 seconds every time.

@allistermaguire
Copy link
Contributor

Hi @clowncracker, I am not 99% sure that the fix included wasn't going to fix the disconnecting issue you were experiencing. You can tell if the fix applies to you as there will be INFO messages logged like the one below. Obviously, the %s will have been replaced with the API method and version. Let me know if you have any of these logged.

No matching method %s for supported version %s.

What happens if you restart the VM running HA? not just HA. Does it work for a few days, maybe longer before your disconnection issue reappears?

@clowncracker
Copy link
Author

clowncracker commented Jun 10, 2024

@allistermaguire there doesn't seem to be any difference between restarting HA or restarting the VM. It isn't happening every minute like last time, it's happening sporadically throughout the day, so it's nearly impossible to get a debug log. What's weird is that it always reconnects exactly 11 seconds later every time. Which makes me think the issue is either with HA or with Songpal itself.

I turned on debug logging and I'll post an update once it happens again, so it might be a few hours before I have anything useful to bring. For what it's worth here are the HA logs (I restarted the VM last night, which is why the error only showed up once so far):

Source: components/songpal/media_player.py:198
integration: Sony Songpal (documentation, issues)
First occurred: 6:45:08 AM (1 occurrences)
Last logged: 6:45:08 AM

[None(http://192.168.20.42:10000/sony)] Got disconnected, trying to reconnect
Source: components/songpal/media_player.py:225
integration: Sony Songpal (documentation, issues)
First occurred: 6:45:19 AM (1 occurrences)
Last logged: 6:45:19 AM

[None(http://192.168.20.42:10000/sony)] Connection reestablished

@clowncracker
Copy link
Author

Hi @clowncracker, I am not 99% sure that the fix included wasn't going to fix the disconnecting issue you were experiencing. You can tell if the fix applies to you as there will be INFO messages logged like the one below. Obviously, the %s will have been replaced with the API method and version. Let me know if you have any of these logged.

No matching method %s for supported version %s.

What happens if you restart the VM running HA? not just HA. Does it work for a few days, maybe longer before your disconnection issue reappears?

Here is the debug log. I'd like to note that now Home Assistant has issues starting Songpal when booting HA, but I'm guessing that is a unrelated issue. I didn't bother to bring that up, but you can see that in the logs. I was going to put in a ticket in HA Core for that because I think that's a startup problem. I left it in the logs in case you are curious:

2024-06-10 09:50:39.817 WARNING (MainThread) [homeassistant.components.media_player] Setup of media_player platform songpal is taking over 10 seconds.
2024-06-10 09:50:39.834 WARNING (MainThread) [homeassistant.components.songpal.media_player] [HT-A7000(http://192.168.20.42:10000/sony)] Unable to connect
2024-06-10 09:50:39.847 WARNING (MainThread) [homeassistant.components.media_player] Platform songpal not ready yet; Retrying in background in 30 seconds
2024-06-10 11:25:18.858 WARNING (MainThread) [homeassistant.components.songpal.media_player] [None(http://192.168.20.42:10000/sony)] Got disconnected, trying to reconnect
2024-06-10 11:25:18.858 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Disconnected: Unable to make a request: Received message 257:None is not str: None
2024-06-10 11:25:18.859 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Trying to reconnect in 10 seconds
2024-06-10 11:25:30.419 DEBUG (MainThread) [songpal.device] Got 5 services!
2024-06-10 11:25:30.419 DEBUG (MainThread) [songpal.service] Available protocols for appControl: ['xhrpost:jsonizer', 'websocket:jsonizer']
2024-06-10 11:25:30.419 DEBUG (MainThread) [songpal.service] Using protocol: ProtocolType.WebSocket
2024-06-10 11:25:30.458 DEBUG (MainThread) [songpal.service] Available protocols for audio: ['xhrpost:jsonizer', 'websocket:jsonizer']
2024-06-10 11:25:30.458 DEBUG (MainThread) [songpal.service] Using protocol: ProtocolType.WebSocket
2024-06-10 11:25:30.525 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyVolumeInformation', 'versions': [{'version': '1.0'}]}
2024-06-10 11:25:30.525 DEBUG (MainThread) [songpal.service] Got notifications: [<Notification notifyVolumeInformation, versions=[{'version': '1.0'}], endpoint=http://192.168.20.42:10000/sony/audio>]
2024-06-10 11:25:30.525 DEBUG (MainThread) [songpal.service] Available protocols for avContent: ['xhrpost:jsonizer', 'websocket:jsonizer']
2024-06-10 11:25:30.525 DEBUG (MainThread) [songpal.service] Using protocol: ProtocolType.WebSocket
2024-06-10 11:25:30.589 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyAvailablePlaybackFunction', 'versions': [{'version': '1.0'}]}
2024-06-10 11:25:30.589 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyPlayingContentInfo',
 'versions': [{'authLevel': 'private', 'version': '1.0'}]}
2024-06-10 11:25:30.589 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-10 11:25:30.589 DEBUG (MainThread) [songpal.service] Available protocols for guide: ['websocket:jsonizer']
2024-06-10 11:25:30.589 DEBUG (MainThread) [songpal.service] Using protocol: ProtocolType.WebSocket
2024-06-10 11:25:30.629 DEBUG (MainThread) [songpal.service] Available protocols for system: ['xhrpost:jsonizer', 'websocket:jsonizer']
2024-06-10 11:25:30.629 DEBUG (MainThread) [songpal.service] Using protocol: ProtocolType.WebSocket
2024-06-10 11:25:30.699 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyAlexaRegistrationStatus',
 'versions': [{'authLevel': 'none', 'version': '1.0'}]}
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyPowerStatus',
 'versions': [{'authLevel': 'none', 'version': '1.0'}]}
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifySettingsUpdate',
 'versions': [{'authLevel': 'none', 'version': '1.1'}]}
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifyStorageStatus',
 'versions': [{'authLevel': 'generic', 'version': '1.1'}]}
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.notification] notification payload: {'name': 'notifySWUpdateInfo',
 'versions': [{'authLevel': 'none', 'version': '1.0'}]}
2024-06-10 11:25:30.700 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-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for appControl.getMethodTypes, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for appControl.getVersions, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for audio.getCustomEqualizerSettings, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for audio.getMethodTypes, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for audio.getVersions, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for audio.setCustomEqualizerSettings, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.getMethodTypes, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.getVersions, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.presetBroadcastStation, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.seekBroadcastStation, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.setActiveTerminal, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.startContentBrowsing, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.getContentCount, using 1.3
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for avContent.getContentList, using 1.4
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for guide.getMethodTypes, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for guide.getVersions, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for guide.switchNotifications, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for system.getMethodTypes, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.device] No supported version specified for system.getVersions, using 1.0
2024-06-10 11:25:30.700 DEBUG (MainThread) [songpal.service] getVolumeInformation version 1.1 got called with args (({},)) kwargs ({})
2024-06-10 11:25:30.759 DEBUG (MainThread) [songpal.containers] Missing key output with no default for Volume
2024-06-10 11:25:30.759 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Current volume: Volume: 27/100
2024-06-10 11:25:30.759 DEBUG (MainThread) [songpal.service] getPowerStatus version 1.1 got called with args (()) kwargs ({})
2024-06-10 11:25:30.828 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Got state: Power off
2024-06-10 11:25:30.829 DEBUG (MainThread) [songpal.service] getCurrentExternalTerminalsStatus version 1.0 got called with args (()) kwargs ({})
2024-06-10 11:25:30.889 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-10 11:25:30.889 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Active source: Bluetooth Audio (uri: extInput:btAudio) (active)
2024-06-10 11:25:30.890 DEBUG (MainThread) [songpal.service] getSoundSettings version 1.1 got called with args (({'target': 'soundField'},)) kwargs ({})
2024-06-10 11:25:30.944 DEBUG (MainThread) [songpal.containers] Missing key deviceUIInfo with no default for Setting
2024-06-10 11:25:30.944 DEBUG (MainThread) [songpal.containers] Missing key uri with no default for Setting
2024-06-10 11:25:30.944 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-10 11:25:30.944 DEBUG (MainThread) [homeassistant.components.songpal.media_player] Active sound mode: cinemaStudio
2024-06-10 11:25:30.944 WARNING (MainThread) [homeassistant.components.songpal.media_player] [None(http://192.168.20.42:10000/sony)] Connection reestablished
2024-06-10 11:25:30.944 DEBUG (MainThread) [songpal.service] No notifications available for appControl
2024-06-10 11:25:30.944 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 0x7fca7d21ff60>})
2024-06-10 11:25:30.945 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 0x7fca7d21ff60>})
2024-06-10 11:25:30.946 DEBUG (MainThread) [songpal.service] No notifications available for guide
2024-06-10 11:25:30.946 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 0x7fca7d21ff60>})
2024-06-10 11:25:31.001 DEBUG (MainThread) [songpal.service] Got notification: <NotificationChange enabled: notifyAvailablePlaybackFunction,notifyPlayingContentInfo disabled: notifyExternalTerminalStatus>
2024-06-10 11:25:31.002 DEBUG (MainThread) [songpal.device] No callbacks defined for <NotificationChange enabled: notifyAvailablePlaybackFunction,notifyPlayingContentInfo disabled: notifyExternalTerminalStatus>
2024-06-10 11:25:31.002 DEBUG (MainThread) [songpal.service] Got notification: <NotificationChange enabled: notifyVolumeInformation disabled: >
2024-06-10 11:25:31.002 DEBUG (MainThread) [songpal.device] No callbacks defined for <NotificationChange enabled: notifyVolumeInformation disabled: >
2024-06-10 11:25:31.002 DEBUG (MainThread) [songpal.service] Got notification: <NotificationChange enabled: notifyAlexaRegistrationStatus,notifyPowerStatus,notifySWUpdateInfo,notifySettingsUpdate,notifyStorageStatus disabled: >
2024-06-10 11:25:31.002 DEBUG (MainThread) [songpal.device] No callbacks defined for <NotificationChange enabled: notifyAlexaRegistrationStatus,notifyPowerStatus,notifySWUpdateInfo,notifySettingsUpdate,notifyStorageStatus disabled: >

@rytilahti
Copy link
Owner

I'm wondering if this could be related to home-assistant/core#119626 and home-assistant/core#106589 - i.e., the same sound mode call triggering a different bug on different devices?

Anyway, I think it'd be better to create a new separate issue to track this, as it feels like it's a separate issue.

@clowncracker
Copy link
Author

I'm wondering if this could be related to home-assistant/core#119626 and home-assistant/core#106589 - i.e., the same sound mode call triggering a different bug on different devices?

Anyway, I think it'd be better to create a new separate issue to track this, as it feels like it's a separate issue.

I've created a new ticket here: #156

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants