track info and queue out of sync with reality

[DutchJaFO]

What version of Music Assistant has the issue?

2022.8.1

The problem

I had started a spotify playlist using MA to target my Sonos speakers (which had been grouped in the Sonos app). After a while I checked MA and saw two things : = track display was showing the wrong song and progress indicator not showing any progress = queue itself had not been updated either At the time of screenshot the active song in reality was "Liberty of Action" ... so not even close to the first one in the list.

Error logs are devoid of any

How to reproduce

Unknown at this time.

I did have an automation start a set of playlists using the MA queue command :

`alias: Start muziek (weekend) sequence:

• service: scene.turn_on target: entity_id: scene.luidsprekers metadata: {}
• service: mass.queue_command data: command: play_media uri: - spotify://playlist/2vL2n1YjQVd1rIMTb5zEbN - https://open.spotify.com/playlist/0qHrlAzF0AKCLHrQ3i6WWA - https://open.spotify.com/playlist/0qxXwSOgfNzBYJQqMhwn4n - https://open.spotify.com/playlist/37i9dQZF1DX0xLQsW8b5Zx enqueue_mode: play target: entity_id: media_player.mass_all_sonos_speakers mode: single icon: mdi:file-music `

The playlist that caused the problem I had started in the MA webinterface by targetting one of my Sonos speakers.

Relevant log output

No relevent info found.

Additional information

The MA target "media_player.mass_all_sonos_speakers" is based on a HA group of Sonos speakers. The Sonos speakers themselves are also grouped within the Sonos app. As a result both groups are identical ... but they do have their own queues in MA

What version of Home Assistant Core are your running

2022.8.1

What type of installation are you running?

Home Assistant OS

On what type of hardware are you running?

Generic x86-64 (e.g. Intel NUC)

[DutchJaFO]

Managed to reproduce the situation again :

1. cleared both queues in MA
2. execute script in HA
3. display and queue are out of sync

(Tom Petty playing on speaker system .. )

Possible related log entry : `Logger: music_assistant.stream Source: runner.py:119 First occurred: 6 augustus 2022 om 10:34:21 (26 occurrences) Last logged: 10:18:04

Got stream request for already running stream: 789a1c0430224ee9a2a599641ce80771, playback may be disturbed! Got stream request for already running stream: 625d8b751470426d9990c7cc8da76eba, playback may be disturbed! Got stream request for already running stream: 3d83048972284965a040a9f10a7fecdf, playback may be disturbed! Got stream request for unknown or finished stream: 3d83048972284965a040a9f10a7fecdf Got stream request for already running stream: 52ffef33c82f4141a9dbea4840c85d6e, playback may be disturbed!`

I now suspect that the fact that all Sonos speakers are already grouped is causing the problem as I do have 5 speakers (one set grouped as a stereo pair in Sonos app).

[DutchJaFO]

changing the script to target a single mass entity instead caused a rather odd start of the stream.

problem is identical ... I am seeing 7 background tasks active which may or may not be related ?

Active track at time of screenshot is "Promised land"

[DutchJaFO]

Latest log warnings : Logger: music_assistant.stream Source: runner.py:119 First occurred: 6 augustus 2022 om 10:34:21 (31 occurrences) Last logged: 10:35:32

Got stream request for already running stream: 625d8b751470426d9990c7cc8da76eba, playback may be disturbed! Got stream request for already running stream: 3d83048972284965a040a9f10a7fecdf, playback may be disturbed! Got stream request for unknown or finished stream: 3d83048972284965a040a9f10a7fecdf Got stream request for already running stream: 52ffef33c82f4141a9dbea4840c85d6e, playback may be disturbed! Got stream request for unknown or finished stream: 4c2c20a5362a465396c87ed9fbbd63c8

[marcelveldt]

Like discussed in discord I need to build a small guard in the code to ignore "passive" speakers from the play action so in case you gave a group of grouped speakers, the play commands are only sent to the "leader" player.

[marcelveldt]

Turns out that guard is already there in the code. Can you confirm that MA was able to "detect" your grouped sonos speakers within the HA group ? So do you see the grouped sonos speakers with the grouped icon in the MA interface ?

Can you please test if playback to a single speaker works fine and plays well for hours ? so start playback without the automation or scene to rule that out.

btw: you can ignore the background tasks.

[DutchJaFO]

The sonos speakers automagically group themselves. I do get the impression that every time the group changes (I think because I group/ungroup in the sonos app) a new queue setting gets created, which also appears to 'reset' the queue settings.

New experiment using current HA 2022.8.2 and MA 2022.8.2, which I did with a cleared log I thought I had left the music playing ... but when I got home I saw several issues : = in MA both the HA-group and the MA automagic group of Sonos speakers indicate they are playing = tracking appears to be stuck for both = all mediaplayers in the HA default view show they are playing with the 'all sonos' HA group indicating the song ... = no sound is heard

Log has an interesting warning : 'Logger: music_assistant.stream Source: runner.py:119 First occurred: 06:58:46 (726 occurrences) Last logged: 18:24:44

Got stream request for unknown or finished stream: 4c2c20a5362a465396c87ed9fbbd63c8 Got stream request for already running stream: 176c8f5006624e8fb6e22769027cba95, playback may be disturbed! Got stream request for unknown or finished stream: 176c8f5006624e8fb6e22769027cba95'

Definitely fewere crossed streams compared to previous incident, but total number of occurrences (726 ) is abnormally high. However as I was running with an empty log I can't verify this.

Possibly related log entry : 'Logger: music_assistant.players.stream Source: /usr/local/lib/python3.10/site-packages/music_assistant/controllers/streams.py:594 First occurred: 07:00:17 (1 occurrences) Last logged: 07:00:17

Skip track Ricky Martin - Livin' la Vida Loca due to missing streamdetails Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/music_assistant/controllers/streams.py", line 590, in _get_queue_stream streamdetails = await get_stream_details( File "/usr/local/lib/python3.10/site-packages/music_assistant/helpers/audio.py", line 241, in get_stream_details full_item = await mass.music.get_item_by_uri(queue_item.uri) File "/usr/local/lib/python3.10/site-packages/music_assistant/controllers/music.py", line 231, in get_item_by_uri return await self.get_item( File "/usr/local/lib/python3.10/site-packages/music_assistant/controllers/music.py", line 254, in get_item return await ctrl.get( File "/usr/local/lib/python3.10/site-packages/music_assistant/controllers/media/tracks.py", line 45, in get track = await super().get(*args, **kwargs) File "/usr/local/lib/python3.10/site-packages/music_assistant/controllers/media/base.py", line 164, in get details = await self.get_provider_item(provider_item_id, provider_id) File "/usr/local/lib/python3.10/site-packages/music_assistant/controllers/media/base.py", line 411, in get_provider_item raise MediaNotFoundError( music_assistant.models.errors.MediaNotFoundError: track 0Ph6L4l8dYUuXFmb71Ajnd not found on provider Spotify`

I suspect the auto-skip that occurred also caused related issues with the tracking ?

I also noticed during testing today that I got 50+ background tasks executing as I was browsing through artists and albums.

[DutchJaFO]

I'm seeing a different effect today. There are updates in the HA part of tihe interface, but they are lagging behind in an odd way : It isn't quite the current / next track situation, but it is kind of close.

HA - sonos group appears to be stuck though. (HA -overview : All Sonos mediaplayer from HA and the MA variant.)

I think I will remove the HA sonos group, because it serves no real purpose for me at the moment and it may be confusing the system. And I think the magic stereo-pair in Sonos has kind of messed up the entitiies in HA, because I've had it unlinked a while ago and as it re-linked in Sonos the pair got a different name.

Simplifying the system should make it easier to replicate if the issue still persists. I think I had changed stream-format in MA from FLAC to mp3 ... need to reset them to defaults too in order to get to the most basic scenario and see if the problem persists.

[OzGav]

Thanks for continuing to troubleshoot. Your plan sounds good.

[DutchJaFO]

Steps so far :

1. I've removed the HA sonos group (it served no purpose and could potentially confuse the system)
2. changed the scripts to target one specific Sonos speaker with the mass-prefix. (note : in the UI for the script the name for the MA- and standard variant of a speaker is invisible. Had to check the yaml to be sure
3. cleaned all log entries (using a shell command linked to a script), restarted HA,
4. checked network settings in HA (I had not set 'internet' in network, so set it to my external URL)
5. not quite sure what the internal network should be I've got https set up but the Duck DNS certificate is not valid for internal ip. In the browser this works after I accept the exception for this site.
6. cleared logs again
7. started my script to set my speakers at the desired volume and queue a few spotify songlists
8. I've also reset the 'advanced settings' to 'FLAC' with ICY metadata disabled, which I think is the default.

The initial start of the music was a bit iffy (no music on target speaker, but within a minute I got music playing on the entire system)

Log showed several interesting entries that (IMHO) can only be linked to MA as nothing else was getting triggered and the log had been empty prior.

Error (may not be related but coincidence makes this probable): 'Logger: frontend.js.latest.202208020 Source: components/system_log/init.py:227 First occurred: 23:44:31 (1 occurrences) Last logged: 23:44:31

:0:0 ResizeObserver loop completed with undelivered notifications.'

Warning : 'Logger: music_assistant.stream Source: runner.py:119 First occurred: 23:44:10 (1 occurrences) Last logged: 23:44:10

Got stream request for unknown or finished stream: 4c2c20a5362a465396c87ed9fbbd63c8'

I think this links to the stutter of the streaming music at the start of the script. Am now several songs into the list. Everything is in sync.

One observation : The groupname of the speakers in MA is "Huiskamer + 3"

The queue name in MA is listed as 'Hobbyruimte' (which is the name of the targetted speaker in the script.)

Current conclusions : This kind of suggests that the HA group of speakers was messing with the system, removing it seems like a good idea. And as I think the idea is to make grouping of mediaplayers a feature of MA anyway, so this would be obsolete anyway.

I also suspect that the MA side may be trying to stream to all of the magically grouped speakers at once, or rather it tries to stream to the 'wrong' speaker (maybe 'Huiskamer in my example) which is already getting the stream from the 'Hobby' target courtesy of the Sonos system itself.

-- update -- As I was trying to make a screenshot of the observed difference in queue and speaker names the stream stopped. No new errors in log.

I also remembered that I have a plex-media target in the MA configuration, but that is invisible in the group. I assume that is because the plex media targets only show when they are actively playing media content. I think removing that one should eliminate another potential source of problems in my setup.

[DutchJaFO]

I've updated HA to the latest OS and Core versions that were released yesterday.

I saw something odd today ... (not sure how repeatable this is yet) = used the Sonos app to start a bandcamp playlist = the ma_version of the speakers in HA only showed the first song and didn't display the next one = the regular HA variants of the speakers did update

It appears repeatable ...

Possibly related errors in log : 'Logger: aiohttp.server Source: helpers/network.py:201 First occurred: 19:59:36 (32 occurrences) Last logged: 20:01:25

Error handling request Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/aiohttp/web_protocol.py", line 435, in _handle_request resp = await request_handler(request) File "/usr/local/lib/python3.10/site-packages/aiohttp/web_app.py", line 504, in _handle resp = await handler(request) File "/usr/local/lib/python3.10/site-packages/aiohttp/web_middlewares.py", line 117, in impl return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 60, in security_filter_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/forwarded.py", line 100, in forwarded_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 28, in request_context_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 82, in ban_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 236, in auth_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 136, in handle result = await result File "/usr/src/homeassistant/homeassistant/components/media_player/init.py", line 1121, in get data, content_type = await player.async_get_media_image() File "/config/custom_components/mass/media_player.py", line 327, in async_get_media_image return await super().async_get_media_image() File "/usr/src/homeassistant/homeassistant/components/media_player/init.py", line 565, in async_get_media_image return await self._async_fetch_image_from_cache(url) File "/usr/src/homeassistant/homeassistant/components/media_player/init.py", line 1035, in _async_fetch_image_from_cache url = f"{get_url(self.hass)}{url}" File "/usr/src/homeassistant/homeassistant/helpers/network.py", line 201, in get_url raise NoURLAvailableError homeassistant.helpers.network.NoURLAvailableError '

And the classic : Logger: frontend.js.latest.202208020 Source: components/system_log/init.py:227 First occurred: 10 augustus 2022 om 21:06:36 (8 occurrences) Last logged: 19:59:35

:0:0 ResizeObserver loop completed with undelivered notifications. https://192.168.0.5:8123/frontend_latest/app.933bd729.js:850:0 Error: Failed to execute 'define' on 'CustomElementRegistry': the name "neerslag-card" has already been used with this registry https://dutchjafo.duckdns.org:8123/lovelace-wc/snelkoppelingen?external_auth=1:0:0 Uncaught

Not strictly related, but coincidence is very high for it to not be a factor.

[DutchJaFO]

Linked suggestion for feature : https://github.com/music-assistant/hass-music-assistant/discussions/836

Reason : I suspect that the queue / settings that are driving the grouped speakers may not have identical settings, which may influence the ability of MA to keep them all in sync. At the very least it would give us access to the same functions that we have in script as we can change queue settings for each speaker in our system without having access to the grouped variant that MA appears to be showing.

[marcelveldt]

Did not yet read into the whole history (just got back from holidays) but a few things are important to know (and remember):

1. Each player has its own settings for player specific settings like stream format, max sample rate etc.

2. If you group a player in Sonos it does not create a special group (like cast does) but it simply designates the first player as "master" player and appends childs to it which will output the same music stream.

3. In relation to the above, if a Sonos player is grouped to another player (so it is a "child" of another player), it no longer has any playback controls of its own, no queue of its own etc. The MA interface tries to make that effect very visible by just hiding all child players underneath the parent player.

4. Unlike the cast ecosystem, Sonos speakers can not be in a group (or multiple groups even) and still have standalone control.

5. While the MA interface visually shows the effect of the grouping, the HA interface does not because its a flat hierarchy. If you send play command to multiple grouped Sonos players at once you will end up with a bad experience because the default behavior is to redirect any playback related command to the parent/master player.

Maybe we should introduce Music Assistant groups which can dynamically join speakers to a Sonos speakergroup only when needed (and that group is addressed). Turning "off" the group, will dissolve the Sonos speakergroup. So in fact replicating the cast behavior for Sonos (or any speaker brand).

[DutchJaFO]

If I understand this then if there is a Sonos group with speaker A as a parent and speaker B as a child then :

1. the only controls/queues available are those of speaker A
2. I should only target speaker A with commands
3. weird effects happen when targetting speaker B (and others) in that group

This may actually explain some of the stuff that has been happening, because while my scripts always target the same speaker it isn't always the parent in a Sonos group. Especially if I group/ungroup in the Sonos app I really need to look at what I'm doing in order to get the same parent back, because the 'group all' action appears to pick one at random.

We definitely need a way to make sure the commands are re-directed to the designated parent of a group. Doing it from within MA is the logical choice as you may have to emulate the grouping of different brands to get a consistent behaviour.

[marcelveldt]

The commands should already be redirected to the "sync master" by default in both MA and the HA core integration but we could have missed a few spots. Another bad thing that may happen is if your scripts address multiple Sonos players at once while they're actually grouped. That may result in the "master" player receiving the same command multiple times.

I need to take a look if I can filter out that second situation. So if a playback related command is received, targeted at multiple players at once, filter out duplicates.

I saw some log warnings from you that a stream request was received multiple times, that is exactly the kind of situation I'd expect to happen when the same command is redirected multiple times.

I'll chew on this a bit and let you know once I have something to test.

[DutchJaFO]

yeah ... it figures that the official sonos integration would already take care of that.

A HA group of Sonos speakers is another possible situation where multiple unwanted commands get fired at already grouped Sonos speakers in the set. It may get even weirder/more complicated if there are multiple groups of sonos speakers.

Example : 4 sonos speakers (A, B, C and D) sonos group 1 = A + B (assume A is the parent of this group) Sonos group 2 = C + D (assume C is the parent of this group) HA group with all 4 speakers ... A command targetted at the HA group would have to figure out that it only needs to target speakers A + C.

It would get complicated if the HA group consists of only A + B + C ... We would have to decide if either C+D are still seen as a group or speaker D is ungrouped for the purpose of this command. The former would probably the easiest to solve, but the latter could get messy very quickly and may be impossible to solve.

I think that may have been another factor, but given that I've now removed the HA group it may not be worth investing too much into that concept and keep it as simple as possible.

As long as HA/MA can detect the grouping/ungrouping at runtime we wiil have something that can fit most use cases.

[codeblue11]

I have a similar problem with the track display not showing progress and sometimes showing the wrong song. What's interesting is that everything functions perfect on my laptop and on my Android phone. But when using the HAS app on my Fire HD10 tablet I have these issues.

A couple additional details: -I can play a song from the Fire Tablet and it plays correctly but it will not show it in the status bar as playing. However, I can see the correct status bars on my laptop and phone of the song I played from the tablet. -I can hit the 'next' button from the tablet and it functions to go to the next song in the queue, but the song won't change in the status bar. I can also press the play button and it will restart with the song that's showing in the status bar. -HAS version 2022.12.6 -Music Assistant Version 2022.12.1

A screenshot is below. When the screenshot was taken the music was actually currently playing another song. If I hit the play button on the screen shown, it would start Symphony No.6 from the beginning. If I hit next it would play next in queue. But the screen would remain at 0:59 in Symphony No.6 in both of these situations. My laptop and phone will update correctly..

[Symbiot78]

Hi On newest interation of MA & HA the issue persists. Here's a screenshot of my MA playing and the entity showing idle status

[OzGav]

The latest versions are only patches so please wait until the next full release and we will see what the situation is then

[DutchJaFO]

v2 b1 appears to fix this. So far the artist/song display in the players appears to match the active song. The intermittent nature of this bug makes it difficult to confirm if it is 100% fixed at this point in time

[OzGav]

Yes it seems better to me. Please close this once you are satisfied it is fixed in V2

[DutchJaFO]

There appear to be issues with playback on Sonos v1 (Play:1) and v2 devices (Symfonysk)

I need to enable 'queue flow mode' (advanced device setting in MA v2b1) because without it the playback stops after the first song in the queue. (not good, but at least very consistent 😁 )

It does appear to come at the cost of not having any kind of track progress, which could be considered a feature when this setting is active. I'd love to have progress indicator per track, but OTOH ... if that is the price for having the queue remain in sync then I can live with that.

I haven't checked on a full day of streaming, but once I've done that and the queue remains in sync I will consider this resolved.

[DutchJaFO]

(MA v2b1) update :

• queue flow enabled, because I'm using a mix of v1 and v2 Sonos devices
• queue status in MA does not show which tracks have been played
• MA indicator doesn't show the correct song at all
• mediaplayers in HA do show correct artist, but at the end of a song it's already showing the next one before I hear it in the playback/crossfade (+/- 30 seconds).

I can't set 'crossfade duration' in MA v2b1 ?

[OzGav]

Here is the discussion about this on Discord https://discord.com/channels/753947050995089438/1084437372860641280

[DutchJaFO]

MA v2b4 :

• fresh install
• added spotify provider and let it sync the library
• added smb provider

Playback with default settings has been good. Only two minor interrupts. During the second one the Symfonysk was playing while the Play:1 was silent, but it caught up.

I'm also seeing track progress and queue updates in sync.

Definitely looking good so far.

[OzGav]

What do you think @DutchJaFO can we close this one?

[OzGav]

I’ll close this shortly unless there is still an issue. Cheers.

[DutchJaFO]

MA v2b12 = flow mode needs to be enabled for playback on Sonos v1 devices (or a group that includes a mix)

I think there's only one issue left and that is the display of the active track within MA web-interace itself :

This is after playing several songs, the song listed was the first one in the queue. The displayed queue isn't updating either, which to me suggests these two symptoms are linked and appear to be a pure visual issue.

Compared to MA v1 (which practically never was in sync) I am happy to call this fixed.

[OzGav]

Cool. Thanks for all the testing. Keep reporting on discord or here.