Play/Pause button incorrect, currently playing track incorrect

[lordbah]

What version of Music Assistant has the issue?

2.3.0b23

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

2024.9.1

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

1) Play/Pause buttons in MA and HA show Play when playlist is already playing. 2) Queue shows incorrect track currently playing. (similar to #815)

How to reproduce

Haven't found how to make it happen every time. Just play playlist until it happens. I think I enabled Queue Flow Mode while using an earlier beta, but I can't find it now(??).

Music Providers

Plex local auth

Player Providers

Sonos S1

Full log output

music-assistant.log

https://github.com/user-attachments/assets/450421d1-2b86-43a5-9551-520f960cc963

Additional information

00:16 in video, 16:50:39 in MA log file In HA select the Best playlist and hit Play button on the Playlists icon. MA shows the queue, with "I Wanna Be Sedated" first. HA shows the same track being played. 00:19 thru 03:41 The song is playing, but HA and MA both show the Play button instead of the Pause button. MA does not show any progress within the track. The wrong album cover image is shown (Everly Brothers) but that's due to the contents of my Plex library, ignore it. The track is only 2:29, so presumably around ... 02:48 ? The second track begins playing. Neither UI recognizes this. The MA log file does not recognize this. 03:41 thru 04:35 Same situation, MA shows user trying to remember how to download the MA log. 04:35 (16:55:04) I hit Play in HA, wondering if it will act as Pause. It did not. 04:36 Both UIs show "Peace of Mind" as currently playing. This was song #3 in the shuffled playlist. As if Play was a "Next Track"? 04:38 Both UIs switch to show "I Wanna Be Sedated" as currently playing. 04:44 Both UIs switch to show "Let Me Love You Baby" as currently playing. This was song #2 in the shuffled playlist. These switches happened without any user interaction.

What version of Home Assistant Core are your running

2024.9.1

What type of installation are you running?

Home Assistant Supervised

On what type of hardware are you running?

Linux

[OzGav]

What other players have you tried?

[marcelveldt]

Hmm, you got into a fancy situation where you have flow mode on Sonos while Sonos cant deal with that. We removed flow mode from the sonos config options but its already set in your case. Best is to remove the player completely from config and then either restart MA or reload the sonos provider. That will rediscover the player with a fresh config.

Also, there is something that stands out in your log. Are you sending commands with an automation or something from HA?

• Multiple calls to synced players (you can see them being redirected)
• Playback starts duplicated, as if 2 play_media calls are being executed at the same time

[lordbah]

I haven't tried any other players. I do have a Chromecast I could use if it would be diagnostically helpful.

There would not have been any automated calls from HA during this test. I do have an automation set up to announce person/car detected on camera but I had no company then.

I turned on Queue Flow because I read somewhere to try that when things weren't working quite right. I'll try removing Sonos S1 as you suggest.

[lordbah]

Deleted Sonos S1, restarted MA, added Sonos S1, added a group player in MA named "All Sonos". (The players are also all grouped in the Sonos mobile app. Do they have to be separate there?) I could not reproduce the same issues (but I can keep trying). Instead I got "stops playing early" issues. 00:04 / 21:42:22 Play playlist from HA "Aquarius" begins playing At this time, "Puppet Man" appears as the next track in the queue. I do still see the "redirected" messages in the log. 00:16 / 21:42:32 I turned on Shuffle in MA MA log shows this and then nothing else for 10 minutes (when I finally hit Pause). No entry about one track ending and another one beginning. Now, "The Game of Love" appears as the next track in the queue. It seems like hitting Shuffle did the shuffling right then. 00:16 thru 04:46 Plays normally 04:46 Sound stops 10 seconds early. MA time bar shows 4:39 out of 4:49. Silence 04:56 "Blue Sky" starts playing. This wasn't even on the first page of the original queue or shuffled queue. Does it reshuffle at every track end? Time bar goes out to 5:04 / 4:49 for first track 05:13 MA UI finally admits "Blue Sky" is playing. Time bar starts at 00:16 09:58 Sound stops 10 seconds early for "Blue Sky". Time bar at 04:59 / 05:09. Time bar goes out to 05:19 / 05:09. 10:18 Now playing "Rainy Day Women". Again, not shown in queue. Time bar starts at 0:11. Eventually I hit Pause.

music-assistant2.log

https://github.com/user-attachments/assets/96839ad5-9d2e-4b2b-aa21-58da68d55180

[marcelveldt]

I quickly pushed a fix for this - can you try beta25 (it will be available within 15 minutes) ?

[lordbah]

First run with 25 didn't go well. Hit Play and nothing happened. About 20 seconds later hit Play again, and it started playing, then almost immediately it moved on to track 2 and started playing that. music-assistant3.log

https://github.com/user-attachments/assets/4af3ed4e-3dbc-434d-a6cb-e7bf7256c83b

[lordbah]

That first try may have been while a sync was still in progress, and maybe that had something to do with it not starting to play the first time I hit the button.

[lordbah]

Second try with 25. "Highway to Hell" audio stopped 12 seconds too early. After the remaining time in silence, the queue jumped over 5 items - which were moved into "Played" so we think we played them. "Catfish Blues" also had audio stop 12 seconds too early on at least one speaker, though I thought I heard it continue on a speaker in another room. After the silence, again the queue jumped over 5 items. (I have 5 speakers - coincidence?

https://github.com/user-attachments/assets/d5d1fb1c-5a55-4ab9-91d7-344a4856f6ca

) music-assistant4.log

[lordbah]

I used the Sonos mobile app to separate my speakers, while leaving them grouped in MA. I started a playlist. At first the UI thought a track was playing but no music was coming out of the speakers. I fiddled with a bunch of things and finally it started working again. Still skips 5 tracks after it finishes one. But I didn't see those "redirected" messages. At one point at the end of a track it paused itself (after playing for around 27 minutes). Nothing in the log at that time. I had to come in and hit Play and it resumed.

[marcelveldt]

Did you disable the HA integration to rule out any automation messing with it ? Its almost as if a playback command is targeted at all child players of a sync group at once somehow, instead of just a single time to the group leader.

What kind of group are you using ? Also did you test playing on a single non grouped speaker ?

[lordbah]

Did you disable the HA integration to rule out any automation messing with it ? No, I'm starting the playlist from HA. But I can try that.

What kind of group are you using ? I'm not aware of multiple kinds. In MA Settings I clicked Add Group Player.

Also did you test playing on a single non grouped speaker ? No, but I can try that too.

[lordbah]

Still on b25. Disabled the MA integration in HA. In MA, picked a playlist and hit Play. Audio began playing on only 3 speakers, Bathroom, Basement, Bedroom. Not on the other two, Computer Room and Living Room. The Group Player "All Sonos" does still have all 5 speakers as group members. I did see 2 "redirected" messages in the log from Basement and Bedroom. Seeing those, I launched the Sonos app on my phone and I see that the 3 players which are playing are now grouped. Earlier I left them all ungrouped in the Sonos app. I don't know how just those 3, but not all 5, got regrouped. Is MA grouping usually reflected in the Sonos app (see below, seems like the answer is yes)? At 9:21 in the video I opened the speaker sidebar in MA and the two speakers which aren't playing appear grayed out. They are both powered on. Track 1 played to the end, 5 tracks were skipped, the next track started and played to the end, 4 tracks were skipped, and another track started. All skipped tracks were added to Played. While the tracks were playing is 22:57:43 thru 23:07:54 in the MA log, when nothing else is ever logged. Should I change the Sonos S1 provider log level from global to something else? I see that the HA integration in MA is still enabled. Should I disable that too? I did not see either track stop playing too early.

So, after this test - beyond the end of the log file and video - I opened the speaker sidebar again and hit the power button beside the non-playing speakers (even though I'd think from the fact that they were grayed out that those buttons weren't enabled). Immediately the Sonos mobile app shows them grouped with the rest. If I hit Play those speakers now play too.

music-assistant5.log

https://github.com/user-attachments/assets/4cd450b6-28c8-4ea1-8bc3-9ac406191f23

[lordbah]

Also did you test playing on a single non grouped speaker ?

It doesn't appear to be possible to select a single speaker. What's the secret?

[OzGav]

You need to ungroup them.

[lordbah]

Well that's unexpected and mildly annoying.

I edited the group speaker "All Sonos" and unchecked "Computer Room" and hit Save. The speaker selection sidebar no longer shows Computer Room in the All Sonos expansion, but it doesn't show Computer Room outside of it either, i.e. Computer Room is not selectable. ('Enable this player" is turned on, "Hide this player in the user interface" is NOT turned on)

Well, maybe I have to restart. docker compose down/up. Now the speaker selection still shows All Sonos but also shows "Bathroom +4". If I click on that, it expands as if it were a group speaker, and that group includes Computer Room. Weird. In MA Settings there is no speaker group called "Bathroom +4". I don't know where this came from.

Okay, next most drastic option is to delete the Sonos S1 provider and re-add it. Hmm, now there are no players at all. Usually adding Sonos S1 adds the speakers automatically. Log has 5 of these 2024-09-23 21:09:11.409 WARNING (ThreadPoolExecutor-0_11) [music_assistant.sonos_s1] Failed to add SonosPlayer <SoCo object at ip 192.168.218.115>: 'Invalid player_id: RINCON_000E58AD3FC001400' So ... delete the provider, restart the container, then add the provider. Nope, same log messages, same problem of having zero speakers. Hmm. Suppose those player ids are invalid because the previous incarnation of each speaker hasn't been completely forgotten. $ sudo docker exec -it music-assistant-server sh Is there a database somewhere that I can manually clear? I don't find "RINCON" in /data/settings.json. Or my supposition may be incorrect.

[lordbah]

Delete provider, add provider, enable scan as always, set log level to debug.

2024-09-23 21:23:31.411 DEBUG (ThreadPoolExecutor-0_28) [music_assistant.sonos_s1] Adding new player: {'zone_name': 'Computer Room', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_B8E9375168DA01400', 'serial_number': 'B8-E9-37-51-68-DA:G', 'software_version': '57.21-51190', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '11.14', 'mac_address': 'B8-E9-37-51-68-DA'}
2024-09-23 21:23:31.435 WARNING (ThreadPoolExecutor-0_28) [music_assistant.sonos_s1] Failed to add SonosPlayer <SoCo object at ip 192.168.218.119>: 'Invalid player_id: RINCON_B8E9375168DA01400'
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/providers/sonos_s1/__init__.py", line 384, in do_discover
    self._add_player(soco)
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/providers/sonos_s1/__init__.py", line 459, in _add_player
    self.mass.config.set_raw_player_config_value(
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/controllers/config.py", line 619, in set_raw_player_config_value
    raise KeyError(msg)
KeyError: 'Invalid player_id: RINCON_B8E9375168DA01400'

KeyError. So, maybe correct supposition, but I don't know where to find the old data.

[lordbah]

Oops, can't add a file while editing a comment it seems. Here it is. music-assistant6.log

[OzGav]

The key error is this separate issue https://github.com/music-assistant/hass-music-assistant/issues/2945

Bathroom+4 means you have a speaker called Bathroom and you have grouped four other players to it.

[lordbah]

Ungrouping the speakers in MA did not ungroup them in Sonos-land.

[lordbah]

I switched to b27 and still got KeyError.

2024-09-23 22:23:13.248 DEBUG (ThreadPoolExecutor-0_23) [music_assistant.sonos_s1] Adding new player: {'zone_name': 'Computer Room', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_B8E9375168DA01400', 'serial_number': 'B8-E9-37-51-68-DA:G', 'software_version': '57.21-51190', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '11.14', 'mac_address': 'B8-E9-37-51-68-DA'}
2024-09-23 22:23:13.282 ERROR (MainThread) [music_assistant] Error doing task: Exception in callback ConfigController.set_raw_player_config_value('RINCON_B8E9375168DA01400', 'flow_mode', False)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/controllers/config.py", line 619, in set_raw_player_config_value
    raise KeyError(msg)
KeyError: 'Invalid player_id: RINCON_B8E9375168DA01400'
2024-09-23 22:23:13.283 INFO (MainThread) [music_assistant.players] Player registered: RINCON_B8E9375168DA01400/Computer Room

But the player does appear in the UI now. But only as part of the "Bathroom +4" group (Sonos group, not MA group, but seems to work the same as an MA group...?). So ... delete the provider, use the mobile Sonos app to ungroup everything, re-add the provider. MA logs that it has "regrouped" all of the speakers 2024-09-23 22:30:29.769 DEBUG (MainThread) [music_assistant.sonos_s1] Regrouped Bathroom: ['RINCON_B8E93751697201400'] yet they appear all ungrouped in MA. So finally I can do the requested test of playing a playlist to one speaker.

It started the first track Aquarius. I saw in the log that it enqueued two more tracks immediately: Puppet Man and Night Time. I realized that shuffle was off, so I clicked it on. The first track played to the end. Then it started playing Slide It In which wasn't shown on the UI queue at all at that point. It took 30 seconds before the MA UI changed currently playing from Aquarius to Slide It In. The log shows it enqueued several songs but they did not get played before Slide It In. While this song was playing, Played showed 7, which included Night Time and the skipped songs. Slide It In played to the end, then Take Me For a Little While began playing (MA UI updated almost immediately this time). Again the log shows several songs enqueued which didn't actually play, but did get added to Played, which shows 14 now. music-assistant8.log

[lordbah]

I haven't seen a repeat of the original problems in some time. The current problem is that when a track finishes the player skips over 4-6 tracks, acting as if it did play them (move into Played list on the UI), and plays the one after that. Even without HA and even when playing to a single speaker. And it does still occasionally just stop itself. Here it had queued up the next track, but when "Song on the Radio" finished, the Now Playing screen showed "Maggot Brain" but the audio did not start and the Play/Pause button was showing Play. It stopped itself.

2024-09-26 18:01:21.019 DEBUG (MainThread) [music_assistant.sonos_s1] Enqued next track (Song on the Radio) to player Bathroom
2024-09-26 18:01:23.865 DEBUG (MainThread) [music_assistant.sonos_s1] Enqued next track (Maggot Brain) to player Bathroom
(nothing more)

[marcelveldt]

I can reproduce the skipping tracks issue now - I'l provide a fix soon - been busy last couple of days with other things

[lordbah]

FYI b29 still has the skipping tracks issue.

[maglat]

skipping track issue for me two. latest HA 10.1 (bug was present on earlier HA as well) and MA 2.2.7 Addon from Hasc. Tracks finish some seconds too early, next track play for 1 second than skip to next. source spotify, player sonos. playing on single sonos or grouped do not make any difference.

[marcelveldt]

fixed in 2.3.0 rc 1

[OzGav]

2.3.0rc1 is released. Please test again

[OzGav]

This will be closed soon assuming fixed