Display support for Slimproto players floods the client with unhandled grfe message

[cociweb]

What version of Music Assistant has the issue?

2.0.0b135

What version of the Home Assistant Integration have you got installed?

2024.3.6

Have you tried everything in the Troubleshooting FAQ and reviewed the Open and Closed Issues and Discussions to resolve this yourself?

• [X] Yes

The problem

I'm trying to swap my LMS docker server with a standalone mass-docker. I have a GioF71/squeezelite-docker player on another machine (same with large/hassio-addons). It is properly parameterized and properly working with LMS. After I try to swap to MASS-docker, my (slimproto) player gives the following error messages at startup:

[02:23:16.648617] process:532 unhandled vers
[02:23:16.650146] process:532 unhandled grfb
[02:23:16.657209] process:532 unhandled grfe
[02:23:16.663336] process:532 unhandled grfe
[02:23:16.675444] process:532 unhandled grfe

after that every 5 sec I get: [02:23:21.662324] process:532 unhandled grfe

tracking the timestamps, the player (DE:AD:BE:EF:F0:0D/Player) is connected and registered on MASS side, at startup but nothing further logs (neither in verbose log) which are in parallel with the client errors.

During start of the play (source does not matter), it gives more unhandled messages on the client side then MASS stops playing after a few secs without any (non-debug) log. On the player side nothing started.

On last year (b70-90) I had some success to play from mass, but for long time, it is impossible.

How to reproduce

start mass server, then start docker: GioF71/squeezelite-docker or large/hassio-addons in HA.

Music Providers

N/A (file-system, yt, tune-in, plex)

Player Providers

slimproto

Full log output

2024-04-13 02:23:12.307 INFO (MainThread) [music_assistant] Starting Music Assistant Server (bb0faf8c4266475091e337fa0ba2dcae) version 2.0.0b135 - HA add-on: False
2024-04-13 02:23:12.322 INFO (MainThread) [music_assistant.cache] Initializing cache controller...
2024-04-13 02:23:12.336 INFO (MainThread) [music_assistant.webserver] Starting server on  0.0.0.0:8095 - base url: https://example.org
2024-04-13 02:23:12.562 INFO (MainThread) [music_assistant.music] Using a sync interval of 180 minutes.
2024-04-13 02:23:12.876 INFO (MainThread) [music_assistant.streams] Detected ffmpeg version 6.0.1 with libsoxr support
2024-04-13 02:23:12.877 INFO (MainThread) [music_assistant.streams] Starting server on  0.0.0.0:8097 - base url: http://192.168.1.100:8097
2024-04-13 02:23:13.660 INFO (MainThread) [music_assistant] Loaded metadata provider fanart.tv Metadata provider
2024-04-13 02:23:13.660 INFO (MainThread) [music_assistant] Loaded metadata provider MusicBrainz Metadata provider
2024-04-13 02:23:13.661 INFO (MainThread) [music_assistant] Loaded metadata provider TheAudioDB Metadata provider
2024-04-13 02:23:13.661 INFO (MainThread) [music_assistant] Loaded music provider URL
2024-04-13 02:23:13.662 INFO (MainThread) [music_assistant] Loaded music provider Tune-In Radio
2024-04-13 02:23:13.662 INFO (MainThread) [music_assistant] Loaded player provider ugp
2024-04-13 02:23:13.734 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2024-04-13 02:23:13.803 INFO (MainThread) [music_assistant] Loaded player provider UPnP/DLNA Player provider
2024-04-13 02:23:13.817 INFO (MainThread) [music_assistant] Loaded player provider Slimproto
2024-04-13 02:23:13.819 INFO (MainThread) [music_assistant.providers.filesystem_smb] Mounting //SERVER/Link/Media/MP3 to /tmp/filesystem_smb
2024-04-13 02:23:13.845 INFO (MainThread) [music_assistant] Loaded music provider Filesystem (remote share)
2024-04-13 02:23:13.850 INFO (MainThread) [music_assistant] Loaded plugin provider Home Assistant
2024-04-13 02:23:14.128 INFO (MainThread) [music_assistant] Loaded music provider RadioBrowser
2024-04-13 02:23:14.556 INFO (MainThread) [music_assistant] Loaded music provider Plex Media Server
2024-04-13 02:23:14.812 INFO (MainThread) [music_assistant] Loaded music provider YouTube Music
2024-04-13 02:23:16.641 INFO (MainThread) [music_assistant.providers.slimproto] Player squeezeplay: DE:AD:BE:EF:FE:ED connected
2024-04-13 02:23:16.646 INFO (MainThread) [music_assistant.players] Player registered: DE:AD:BE:EF:FE:ED/squeezeplay: DE:AD:BE:EF:FE:ED
2024-04-13 02:23:16.647 INFO (MainThread) [music_assistant.players] Player registered: syncgroup_i5vyao4w/Yard-Slimproto
2024-04-13 02:23:16.654 INFO (MainThread) [music_assistant.providers.slimproto] Player squeezeplay: DE:AD:BE:EF:F0:0D connected
2024-04-13 02:23:16.659 INFO (MainThread) [music_assistant.players] Player registered: DE:AD:BE:EF:F0:0D/Player

Additional information

No response

What version of Home Assistant Core are your running

2024.4.3

What type of installation are you running?

Home Assistant Supervised

On what type of hardware are you running?

Linux

[OzGav]

https://music-assistant.io/installation/#server-notes

please confirm you aren’t running LMS and the slimproto player at the same time on the same network

please also add everything that you have tried or confirmed from the troubleshooting page in the docs that hasn’t helped.

[cociweb]

Ofc, only LMS OR MASS is running on the same time, HA has no slim* integration too. I have only these two squeezelite integrations on the same L2 layer. http/https (reverse proxy) does not matter, docker uses the host's network, all the required ports are opened (also tried with network_mode: host on client side too; also tried with temporarily turned-off firewall on both sides). Ofc I've went through all of the troubleshooting steps... (the client is connected and registered)

Additionally, the display support also disabled (with exactly same sdebug log sequence for the grfe): https://github.com/ralph-irving/squeezelite/issues/219

Additionally the unhandled vers refers to this sdebug log on the client:

[04:56:23.339000] sendHELO:148 mac: DE:AD:BE:EF:F0:0D
[04:56:23.339045] sendHELO:150 cap: CanHTTPS=1,Model=squeezelite,AccuratePlayPoints=1,HasDigitalOut=1,HasPolarityInversion=1,Balance=1,Firmware=v1.9.9-1414,ModelName=SqueezeLite,MaxSampleRate=192000,dsf,dff,alc,wma,wmap,wmal,aac,ogg,ops,ogf,flc,aif,pcm,mp3
[04:56:23.343091] process:532 unhandled vers

[marcelveldt]

Go into the player settings and make sure that display support is disabled.

Also its safe to ignore these warning. Remember that MA is not a full drop in replacement for a full LMS server (with a 25 year history) - we just implemented what is enough to provide proper playback and didnt implement every quirk.

[marcelveldt]

I suggest you to first test it with a squeezelite client on your local pc or whatever. We have 100's, maybe 1000s of folks running picoreplayer or other squeezelite based players successfully. Its even my de-facto test player at all times, so I'm 99,9% sure that playback should work awesome ;-)

[cociweb]

Neither disabling the display support (nor enabling with NONE or with the rest options) brings no change for me at none of the the latest-stable squeezelite based players.

In the meantime I've found the guilty PR: #1131 with the b106 the log is not coming, with the b107 it is coming. Since this PR contains a lot of big improvements (such as aioslimproto upgrade and........adding display support feature....) it is hard to tackle down the exact root cause for me.

.....and as of now, we should separate the process:532 unhandled grfe and process:532 unhandled vers logs into two tickets, because the unhandled vers should be an older issue. it is also visible with b0.

[cociweb]

I've added some debug log self.logger.debug("Send_Frame: %s", packet) into send_frame in aioslimproto/client and I'm getting this in every 5 secs when display support is turned off. the source of the GFRE is here:

2024-04-15 03:10:06.956 DEBUG (MainThread) [aioslimproto.client.playername] Send_Frame: b'\x00\x1cstrmt0p1321\x000\x000\x00\x00\x00\x00\x00\x00\x02\x00\x00\x00\x00\x00\x00'
2024-04-15 03:10:06.961 DEBUG (MainThread) [aioslimproto.client.playername] Send_Frame: b'\x02\x08grfe\x00\x00c\x00\x00\x00\x00\x00\x00\xff\x00\x00\x03\xff\xc0\x00\x07\xff\xe0\x00\x0f\xff\xf0\x00\x0e\x00p\x00\x0e\x00p\x00\x0e\x00p\x00\x0f\x00\xf0\x00\x0f\xff\xf0\x00\x07\xff\xe0\x00\x03\xff\xc0\x00\x00~\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xf0\x00\x0e\x00p\x00\x0e\x00p\x00\x0e8p\x00\x0e8p\x00\x0e8p\x00\x0e<p\x00\x0f\xff\xf0\x00\x0f\xff\xf0\x00\x07\xef\xe0\x00\x03\xc7\xc0\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xf0\xf0\x00\x00\xf0\xf0\x00\x00\xf0\xf0\x00\x00\xf0\xf0\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x06\x00p\x00\x0e\x00p\x00\x0e\x00p\x00\x0e\x00p\x00\x0f\xff\xf0\x00\x0f\xff\xf0\x00\x0f\xff\xf0\x00\x00\x00p\x00\x00\x00p\x00\x00\x00p\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xff\x00\x00\x03\xff\xc0\x00\x07\xff\xe0\x00\x0f\xff\xf0\x00\x0e\x00p\x00\x0e\x00p\x00\x0e\x00p\x00\x0f\x00\xf0\x00\x0f\xff\xf0\x00\x07\xff\xe0\x00\x03\xff\xc0\x00\x00~\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00'

[Paul-Vdp]

Suffering from the same error spamming with the utterly simple setup of the squeezelite addon (supervised install), connected to the Local Aux output. Much worse : cannot get any sound from it when discovered/configured in MASS as a simple Slimproto/Squeezelite player ...

[marcelveldt]

unhandled vers is unavoidable - we are not LMS ! as for unhandled grfe - why does it matter ? Its just a log you will not see. It wont affect playback or performance, nothing. Its just the squeezelite reporting it got a command it can not handle itself.

No big deal. Sure, nice to fix it but if someone has playback issues it will not have anything to do with that log

[marcelveldt]

marked as bug to be fixed (the display code should not be called, that is why you see that grfe message). we'll fix this soon when time allows it but before the official 2.0 release.

For playback issues, please create a new issue as that is completely unrelated to having 'unhandled grfe' or vers messages in your squeezelite log (like I said above, that is just squeezelite saying it received a command it has no handler for)

[cociweb]

unhandled vers is unavoidable - we are not LMS !

ok, it's acceptable. I've played a few hours yesterday but it was unsuccessful in my time-box based manner. You are right, it just a log entry as a response for the helo_process...

marked as bug to be fixed

Great, thank's! I'm glad to be useful to uncover a misbehavior.

For the playback issue, as of now, I see that it is irrelevant for the above mentioned logs, but as I see it is confirmed by others as well.

[Paul-Vdp]

Well, release 2.0 has come and gone ... :-(

[marcelveldt]

Well, release 2.0 has come and gone ... :-(

Is there anything you want to say here ?

Remember that this is just a log - we have much more important things to handle. A workaround has been PR'ed and merged and it will be in the next update.

[Paul-Vdp]

Was just referring to what you said on Apr 15 'we'll fix this soon when time allows it but before the official 2.0 release'. Anyway, happy to hear salvation is on the way ;-)

[cociweb]

when time allows it

The time did not allow it. The contribution is open for everyone. Everyone mean implicitly You as well.

Anyway, happy to hear salvation is on the way ;-)

I'm also very happy to do any contribution (bug find, report then resolve) on my own, in my free time, for You: the community. ;)

I'm glad and really appreciate your appreciation.

[marcelveldt]

Now that the fix (to set display options OFF by default) I think its safe to close this bug report ?

[Paul-Vdp]

As far as I'm concerned: YES ! And thanks for taking care of our overflowing logs ;-)