search

rytilahti / python-songpal

Python library for interfacing with Sony's Songpal devices
GNU General Public License v3.0
66 stars 24 forks source link

Sony Songpal becomes unavailable/available every minute #151

Closed clowncracker closed 8 months ago

clowncracker commented 8 months ago

Opening a ticket here per: https://github.com/home-assistant/core/issues/111121.

It looks like the cause of the issue is https://github.com/rytilahti/python-songpal/pull/145.

rytilahti commented 8 months ago

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 commented 8 months ago

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

rytilahti commented 8 months ago

Thanks :+1: 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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

@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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

Hey @clowncracker, it should, as a dependency it will download and install. I have looked at https://github.com/home-assistant/core/issues/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 commented 8 months ago

@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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

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

rytilahti commented 8 months ago

https://github.com/home-assistant/core/pull/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! :100:

clowncracker commented 5 months ago

@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 commented 5 months ago

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 commented 5 months ago

@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 commented 5 months ago

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 commented 5 months ago

I'm wondering if this could be related to https://github.com/home-assistant/core/issues/119626 and https://github.com/home-assistant/core/pull/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 commented 5 months ago

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: https://github.com/rytilahti/python-songpal/issues/156