Inconsistent state reported by Sonos ‘State’ channels

I’m building a rule which groups two sonos devices as long as one (the sonos Roam) is on its charger. Unfortunately, this approach works in most but not all scenarios.

It appears that the rule falls down because ‘state’ Items (e.g. channel="sonos:Roam:roam:state") seem to be reported inconsistently - i.e. a speaker may report a state of “PLAYING” when it in fact is not playing anything (or “STOPPED” but is in reality playing etc.).

This appears to happen whenever localcoordinator speakers are ungrouped:

Scenario A - Removal of a grouped speaker which is not localcoordinator:

  1. Start music on Speaker A
  2. Add Speaker B to Speaker A group (Speaker A is localcoordinator)
  3. Remove Speaker B from the group
  4. Speaker A continues playing and Speaker B stops :heavy_check_mark:
    a_sonos_state reports “PLAYING”, b_sonos_state reports “STOPPED” :heavy_check_mark:

Scenario B - Removal of localcoordinator from the group:

  1. Start music on Speaker A
  2. Add Speaker B to Speaker A group (Speaker A is localcoordinator)
  3. Remove Speaker A from the group
  4. Speaker A stops and Speaker B continues playing :heavy_check_mark:
    a_sonos_state reports “STOPPED”, b_sonos_state reports “STOPPED” :heavy_multiplication_x:

Scenario A exhibits the expected behaviour: state items are accurate to what’s playing.
In Scenario B, music continues to play on Speaker B (intended behaviour) while it is reported as “STOPPED”.

I can confirm that this issue persists no matter where the command originates (openHAB rule, sonos app, Alexa command or physical buttons). It also affects the control channel, as can be seen here:


In reality, this speaker is playing music but shows as “PAUSE” and “STOPPED”

I’ve scoured the forums for clues, including @buschif4’s excellent Multiroom Rule but I’ve not seen other reports of this. Hoping someone else has experienced this problem and found a reason/solution.

In the meantime, here are my things, items and rules in case it sheds any light:

sonos.things

Thing sonos:One:kitchen	"Sonos Kitchen" @ "Kitchen" [ udn="RINCON_7828CAF3E95801400"]
Thing sonos:Roam:roam	"Sonos Roam" 	@ "Roam"	[ udn="RINCON_542A1B41B73801400"]

sonos.items

Group		gSonosStates 	"Sonos States"
Group		gSonosID 		"Sonos ID Group"
Group		gSonosRemove 	"Sonos REMOVE Group"
Group		gSonosAdd 		"Sonos ADD Group"
Group		gSonosVol 		"Sonos Volume Group"
Group		gSonos 			"Sonos"

//////////KITCHEN//////////
Group		gSonosK
String		k_sonos_zonename	"ID"	    	(gSonos, gSonosK)	            	{channel="sonos:One:kitchen:zonename"}
Player		k_sonos_control		"Control [%s]"	(gSonos, gsonosK)					{channel="sonos:One:kitchen:control"}
Dimmer		k_sonos_vol			"Volume"		(gSonos, gsonosK, gSonosVol)		{channel="sonos:One:kitchen:volume"}
String		k_sonos_add			"Add [%s]"		(gSonos, gsonosK, gSonosAdd)		{channel="sonos:One:kitchen:add"}
String		k_sonos_remove		"Remove [%s]"	(gSonos, gsonosK, gSonosRemove)		{channel="sonos:One:kitchen:remove"}
String		k_sonos_state		"State"			(gSonos, gsonosK, gSonosStates)		{channel="sonos:One:kitchen:state"}	
Switch		k_sonos_master		"Master"		(gSonos, gsonosK, gSonosMaster)		{channel="sonos:One:kitchen:localcoordinator"}
String		k_sonos_groupid		"Group ID"		(gSonos, gsonosK, gSonosID)			{channel="sonos:One:kitchen:zonegroupid"}

//////////ROAM//////////
Group		gSonosR
String		r_sonos_zonename	"ID"	    	(gSonos, gSonosR)	            	{channel="sonos:Roam:roam:zonename"}
Player		r_sonos_control		"Control [%s]"	(gSonos, gSonosR)					{channel="sonos:Roam:roam:control"}
Dimmer		r_sonos_vol			"Volume"		(gSonos, gSonosR, gSonosVol)		{channel="sonos:Roam:roam:volume"}
String		r_sonos_add			"Add [%s]"		(gSonos, gSonosR, gSonosAdd)		{channel="sonos:Roam:roam:add"}
String		r_sonos_remove		"Remove [%s]"	(gSonos, gSonosR, gSonosRemove)		{channel="sonos:Roam:roam:remove"}
String		r_sonos_state		"State"			(gSonos, gSonosR, gSonosStates)		{channel="sonos:Roam:roam:state"}
Switch		r_sonos_master		"Master"		(gSonos, gSonosR, gSonosMaster)		{channel="sonos:Roam:roam:localcoordinator"}
String		r_sonos_groupid		"Group ID"		(gSonos, gSonosR, gSonosID)			{channel="sonos:Roam:roam:zonegroupid"}
Switch		r_sonos_charging	"Charging"	    (gSonos, gSonosR)		            {channel="sonos:Roam:roam:batterycharging"}

sonos.rules

rule "SONOS ROAM Sync 1"
when
	Item r_sonos_state changed to PLAYING
then
	if (r_sonos_groupid.state != k_sonos_groupid.state && r_sonos_charging.state == ON) {
		Thread::sleep(500)
		if (r_sonos_master.state == OFF) {
			gSonosID.members.forEach[ i |
				var vRoom = transform("JSONPATH", "$.slots[0].value.value", i.name.toString.split('_').get(0))
				if ( i.state == r_sonos_groupid.state
				&& org.openhab.core.model.script.ScriptServiceUtil.getItemRegistry.getItem(vRoom + "_sonos_zonename").state != "Sonos Roam"
				&& org.openhab.core.model.script.ScriptServiceUtil.getItemRegistry.getItem(vRoom + "_sonos_zonename").state != "Kitchen"
				&& org.openhab.core.model.script.ScriptServiceUtil.getItemRegistry.getItem(vRoom + "_sonos_master").state == ON ) 
					org.openhab.core.model.script.ScriptServiceUtil.getItemRegistry.getItem(vRoom + "_sonos_add").sendCommand("kitchen")
		]	}
		else if (r_sonos_master.state == ON)
			r_sonos_add.sendCommand("kitchen")
		k_sonos_vol.sendCommand(r_sonos_vol.state)
	}
end
rule "SONOS ROAM Sync 2"
when
	Item k_sonos_state changed to PLAYING
then
	if (r_sonos_groupid.state != k_sonos_groupid.state && r_sonos_charging.state == ON)  {
		Thread::sleep(500)
		if (k_sonos_master.state == OFF) {
			gSonosID.members.forEach[ i |
				var vRoom = transform("JSONPATH", "$.slots[0].value.value", i.name.toString.split('_').get(0))
				if ( i.state == k_sonos_groupid.state
				&& org.openhab.core.model.script.ScriptServiceUtil.getItemRegistry.getItem(vRoom + "_sonos_zonename").state != "Sonos Roam"
				&& org.openhab.core.model.script.ScriptServiceUtil.getItemRegistry.getItem(vRoom + "_sonos_zonename").state != "Kitchen"
				&& org.openhab.core.model.script.ScriptServiceUtil.getItemRegistry.getItem(vRoom + "_sonos_master").state == ON ) 
					org.openhab.core.model.script.ScriptServiceUtil.getItemRegistry.getItem(vRoom + "_sonos_add").sendCommand("roam")
		]	}
		else if (k_sonos_master.state == ON)
			k_sonos_add.sendCommand("roam")
		r_sonos_vol.sendCommand(k_sonos_vol.state)
	}
end

I agree this is not the expected result and I am very surprised.
I can try to reproduce it.
Is it the same if you disable all your rules related to your Sonos devices?

I just tested your scenario A and B and the result is good for me. Sorry I can’t reproduce your problem.
Try to disable your rules in case the problem is caused by one of your rules.

Thanks for trying to reproduce it @Lolodomo.

Unfortunately, all rules were disabled for the above tests. I’ve just repeated these steps and got the same result :frowning:

So far it’s a complete mystery.

For the record I’m running the latest openhab build on a RPi4. OpenHABian and all Sonos devices are up to date.

What music service was used during your tests? Yesterday, my tests were run using TuneIn.

All my previous tests were using Apple Music, initiated via the Sonos App. I’ve just repeated the steps to reproduce this with Amazon Music, TuneIn and Sonos Radio, and the results are the same.

Here are the steps broken down. Once again I’ve made sure to disable all rules for this test:
Note: In the screenshots below, the Sonos app always exhibits the expected behaviour (i.e. it accurately reflects the reality of whether speakers are grouped or playing etc.)

  1. Start playing music in Kitchen [expected behaviour]

  2. Add Conservatory to Kitchen (Kitchen is localcoordinator) [expected behaviour]

  3. Remove Conservatory from Kitchen [expected behaviour]

  4. Add Conservatory to Kitchen again (Kitchen is localcoordinator) [expected behaviour]

  5. Remove Kitchen from Kitchen group

  • Sonos App: Speakers are ungrouped and music plays on Conservatory [expected behaviour]
  • OpenHAB: Both speakers are reported as PAUSE & STOPPED by Control & State channels [unexpected behaviour]
    Exepected behaviour: Conservatory should continue to report a PLAYING state and Group Name should become Conservatory. All Kitchen items are being reported correctly, as is the Conservatory master state, which turns ON.
  1. Add Kitchen to Conservatory (Conservatory is localcoordinator)
  • Sonos App: Speakers are grouped and music plays both speakers [expected behaviour]
  • OpenHAB: Both speakers continue to be reported as PAUSE & STOPPED by Control & State channels. Group Name continues to be Kitchen [unexpected behaviour]
    Exepected behaviour: State is PLAYING and Group Name is Conservatory for both speakers.
  1. Remove Conservatory from Conservatory group [expected behaviour]

So it appears that it is not just the Control and State channels that are reporting inaccurately, but also the “Group Name” (which is my friendly name for zonegroupid)

I’ve had this issues for a few years now. I had to setup a non binding item to audit the actual state of each sonos speaker.

Its my belief it’s about a few things:

  1. Most of my speakers are in pairs

  2. When grouping speakers then stopping the primary pair, the other grouped speakers don’t get updated to stop (they stop but actually are in playing state still)

  3. When speakers are in pairs; there is a per se “Master” of the pair. Sometimes, when I stop the perceived master, the other speaker stops playing but it still has a playing state.

My Sonos system is up to date on firmware updates. I have 16 speakers, majority of them are in pairs. 75% of the speakers are wired; rest are wireless running through Unifi wireless.

I play Sonos Radio now, use to play Spotify - both have the same results.

I’m running OH 3.2 on Pi.

Best, Jay

Hi Jay. Thanks for sharing your experience.

None of my speakers are in pairs, so it appears the issue is not related to that.

Points 2 and 3 are exactly what I’m experiencing. Using the the steps above I can reproduce the issue reliably, which seems to occur as soon as a “Master” speaker (localcoordinator) is ungrouped. After that, there are multiple inconsistencies.

Does this mean you were able to capture the actual state of each speaker using an alternative method? If so, I’d be interested in knowing how.

Here’s what I’m doing - it’s NOT perfect but it does work most of the time.

items:

Group  gSonosLoftState																									
String Sonos_Loft_State  					"State [MAP(sonos.map):%s]"                    (gSState, SonosState, Group_HabPanel_Dashboard, gSonosLoftState)			{ channel="sonos:PLAY1:RINCON_7828CA321F3001400:state" }
String Sonos_Loft_CurrentTrack				"Now playing [%s]" 			    	(gSonosCurrentTrack, Group_HabPanel_Dashboard, gSonosLoftState) 					{ channel="sonos:PLAY1:RINCON_7828CA321F3001400:currenttrack" }
String Sonos_Loft_CurrentAlbumCoverArtURL	"Sonos URL [%s]"					(gSonosAlbumCoverArtURL, ResetExpire, gSonosLoftState)					 			{ channel="sonos:PLAY1:RINCON_7828CA321F3001400:currentalbumarturl", expire="10m, state=http://192.168.0.32:8080/static/images/noimage.jpg" }

rule (one for each speaker):

rule "Sonos Loft Controller Check URL and Track"
    when
		Member of gSonosLoftState changed
    then

		if (systemStarted.state != ON && OH_Uptime_HumanReadable.state != NULL && OH_Uptime_HumanReadable.state !== null && OH_Uptime_HumanReadable.state.toString() != 'UNDEF') {

			logInfo("tAlive","CREATING Generic 167 Timer!")
			createTimer(now().plusNanos(5000), [ |

				if (systemStarted.state != ON && (Sonos_Loft_CurrentAlbumCoverArtURL.state === null || Sonos_Loft_CurrentAlbumCoverArtURL.state.toString() == 'UNDEF')) {	
				
					Sonos_Loft_CurrentAlbumCoverArtURL_Proxy.postUpdate(DummyImageURL)
					Sonos_Loft_CurrentTrack.postUpdate(DummyTrack)
		
					Sonos_Loft_Controller.postUpdate('PAUSE')
					Sonos_Loft2_Controller.postUpdate('PAUSE')	
		
					Sonos_Loft_State.postUpdate('STOPPED')
					Sonos_Loft2_State.postUpdate('STOPPED')	
		
				} else {
		
					Sonos_Loft_CurrentAlbumCoverArtURL_Proxy.postUpdate(Sonos_Loft_CurrentAlbumCoverArtURL.state)
					Sonos_Loft2_CurrentAlbumCoverArtURL_Proxy.postUpdate(Sonos_Loft2_CurrentAlbumCoverArtURL.state)
				}	

				if (systemStarted.state != ON && (Sonos_Loft2_CurrentAlbumCoverArtURL.state === null || Sonos_Loft2_CurrentAlbumCoverArtURL.state.toString() == 'UNDEF')) {	
				
					Sonos_Loft2_CurrentAlbumCoverArtURL_Proxy.postUpdate(DummyImageURL)
					Sonos_Loft2_CurrentTrack.postUpdate(DummyTrack)
		
					Sonos_Loft_Controller.postUpdate('PAUSE')
					Sonos_Loft2_Controller.postUpdate('PAUSE')
		
					Sonos_Loft_State.postUpdate('STOPPED')
					Sonos_Loft2_State.postUpdate('STOPPED')	
		
				} else {
		
					Sonos_Loft_CurrentAlbumCoverArtURL_Proxy.postUpdate(Sonos_Loft_CurrentAlbumCoverArtURL.state)
					Sonos_Loft2_CurrentAlbumCoverArtURL_Proxy.postUpdate(Sonos_Loft2_CurrentAlbumCoverArtURL.state)
				}	
			])
		}
end

Best, Jay

Maybe we could avoid mixing different “problems”. Pairs is clearly something not yet implemented in the binding (sorry, I have no devices that I can pair).

To come back to the initially reported problem (ungrouping), could you please enable TRACE logs (log:set TRACE org.openhab.binding.sonos) and then show the result of this command when you run the scenario that leads to unexpected result (step 5 in your scenario): grep “TransportState” openhab.log

2022-08-10 18:05:54.020 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'LastChange':'<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/"><InstanceID val="0"><TransportState val="TRANSITIONING"/><CurrentPlayMode val="NORMAL"/><CurrentCrossfadeMode val="0"/><NumberOfTracks val="3"/><CurrentTrack val="1"/><CurrentSection val="0"/><CurrentTrackURI val="hls-radio://https://prod-pre.fns.tunein.com/v1/master/30ead7055f8b8e1f2f04add745f139b184df6925/prod_preroll/preroll0.m3u8?ads.cust_params=partnerId%253dSonos%2526ads_partner_alias%253dceSonos%2526version%253d57.12%2526premium%253dfalse%2526abtest%253d%2526language%253den-US%2526stationId%253ds6586%2526is_ondemand%253dfalse%2526genre_id%253dg54%2526class%253dmusic%2526is_family%253dfalse%2526is_mature%253dfalse%2526country_region_id%253d80%2526station_language%253dfrench%2526programId%253dp1086126%2526is_event%253dfalse&amp;ads.stationId=s6586&amp;ads.ads_partner_alias=ceSonos&amp;ads.url=https%3a%2f%2ftunein.com%2fdesc%2fs6586%2f&amp;ads.description_url=https%3a%2f%2ftunein.com%2fdesc%2fs6586%2f&amp;ads.npa=1&amp;ads.gdfp_req=1&amp;ads.is_lat=1"/><CurrentTrackDuration val="0:00:00"/><CurrentTrackMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;res protocolInfo=&quot;sonos.com-http:*:audio/mpegurl:*&quot;&gt;x-sonosapi-stream:s6586?sid=254&amp;amp;flags=32&lt;/res&gt;&lt;r:streamContent&gt;&lt;/r:streamContent&gt;&lt;r:radioShowMd&gt;Bob,p1086126&lt;/r:radioShowMd&gt;&lt;upnp:albumArtURI&gt;/getaa?s=1&amp;amp;u=x-sonosapi-stream%3as6586%3fsid%3d254%26flags%3d32&lt;/upnp:albumArtURI&gt;&lt;dc:title&gt;x-sonosapi-stream:s6586?sid=254&amp;amp;flags=32&lt;/dc:title&gt;&lt;upnp:class&gt;object.item&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/><r:NextTrackURI val=""/><r:NextTrackMetaData val=""/><r:EnqueuedTransportURI val="x-sonosapi-stream:s6586?sid=254&amp;flags=32"/><r:EnqueuedTransportURIMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;dc:title&gt;OUI FM&lt;/dc:title&gt;&lt;upnp:class&gt;object.item.audioItem.audioBroadcast&lt;/upnp:class&gt;&lt;desc id=&quot;cdudn&quot; nameSpace=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot;&gt;SA_RINCON65031_&lt;/desc&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/><PlaybackStorageMedium val="NETWORK"/><AVTransportURI val="x-sonosapi-stream:s6586?sid=254&amp;flags=32"/><AVTransportURIMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;dc:title&gt;OUI FM&lt;/dc:title&gt;&lt;upnp:class&gt;object.item.audioItem.audioBroadcast&lt;/upnp:class&gt;&lt;desc id=&quot;cdudn&quot; nameSpace=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot;&gt;SA_RINCONxxxxx_&lt;/desc&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/><CurrentTransportActions val="Set, Stop, Play"/><r:CurrentValidPlayModes val=""/></InstanceID></Event>' (service 'AVTransport') for thing 'sonos:PLAY5:chambre'
2022-08-10 18:05:54.196 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'TransportState':'TRANSITIONING' (service 'AVTransport') for thing 'sonos:PLAY5:chambre'
2022-08-10 18:05:54.325 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'LastChange':'<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/"><InstanceID val="0"><TransportState val="STOPPED"/><CurrentPlayMode val="NORMAL"/><CurrentCrossfadeMode val="0"/><NumberOfTracks val="1"/><CurrentTrack val="1"/><CurrentSection val="0"/><CurrentTrackURI val="x-sonosapi-stream:s6586?sid=254&amp;flags=32"/><CurrentTrackDuration val="0:00:00"/><CurrentTrackMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;res protocolInfo=&quot;sonos.com-http:*:application/octet-stream:*&quot;&gt;x-sonosapi-stream:s6586?sid=254&amp;amp;flags=32&lt;/res&gt;&lt;r:streamContent&gt;&lt;/r:streamContent&gt;&lt;r:radioShowMd&gt;Bob,p1086126&lt;/r:radioShowMd&gt;&lt;upnp:albumArtURI&gt;/getaa?s=1&amp;amp;u=x-sonosapi-stream%3as6586%3fsid%3d254%26flags%3d32&lt;/upnp:albumArtURI&gt;&lt;dc:title&gt;OUI FM&lt;/dc:title&gt;&lt;upnp:class&gt;object.item&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/><r:NextTrackURI val=""/><r:NextTrackMetaData val=""/><r:EnqueuedTransportURI val="x-sonosapi-stream:s6586?sid=254&amp;flags=32"/><r:EnqueuedTransportURIMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;dc:title&gt;OUI FM&lt;/dc:title&gt;&lt;upnp:class&gt;object.item.audioItem.audioBroadcast&lt;/upnp:class&gt;&lt;desc id=&quot;cdudn&quot; nameSpace=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot;&gt;SA_RINCON65031_&lt;/desc&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/><PlaybackStorageMedium val="NETWORK"/><AVTransportURI val="x-sonosapi-stream:s6586?sid=254&amp;flags=32"/><AVTransportURIMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;dc:title&gt;OUI FM&lt;/dc:title&gt;&lt;upnp:class&gt;object.item.audioItem.audioBroadcast&lt;/upnp:class&gt;&lt;desc id=&quot;cdudn&quot; nameSpace=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot;&gt;SA_RINCONxxxxx_&lt;/desc&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/><CurrentTransportActions val="Set, Stop, Play"/><r:CurrentValidPlayModes val=""/></InstanceID></Event>' (service 'AVTransport') for thing 'sonos:CONNECTAMP:bureau'
2022-08-10 18:05:54.470 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'TransportState':'STOPPED' (service 'AVTransport') for thing 'sonos:CONNECTAMP:bureau'
2022-08-10 18:05:54.524 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'TransportState':'TRANSITIONING' (service 'AVTransport') for thing 'sonos:CONNECTAMP:bureau'
2022-08-10 18:05:54.524 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'TransportState':'STOPPED' (service 'AVTransport') for thing 'sonos:PLAY5:chambre'
2022-08-10 18:05:54.579 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'TransportState':'TRANSITIONING' (service 'AVTransport') for thing 'sonos:PLAY5:chambre'
2022-08-10 18:05:54.614 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'TransportState':'STOPPED' (service 'AVTransport') for thing 'sonos:CONNECTAMP:bureau'
2022-08-10 18:05:54.677 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'TransportState':'TRANSITIONING' (service 'AVTransport') for thing 'sonos:CONNECTAMP:bureau'
2022-08-10 18:05:56.091 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'LastChange':'<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/"><InstanceID val="0"><TransportState val="TRANSITIONING"/><CurrentPlayMode val="NORMAL"/><CurrentCrossfadeMode val="0"/><NumberOfTracks val="3"/><CurrentTrack val="1"/><CurrentSection val="0"/><CurrentTrackURI val="hls-radio://https://prod-pre.fns.tunein.com/v1/master/30ead7055f8b8e1f2f04add745f139b184df6925/prod_preroll/preroll0.m3u8?ads.cust_params=partnerId%253dSonos%2526ads_partner_alias%253dceSonos%2526version%253d57.12%2526premium%253dfalse%2526abtest%253d%2526language%253den-US%2526stationId%253ds6586%2526is_ondemand%253dfalse%2526genre_id%253dg54%2526class%253dmusic%2526is_family%253dfalse%2526is_mature%253dfalse%2526country_region_id%253d80%2526station_language%253dfrench%2526programId%253dp1086126%2526is_event%253dfalse&amp;ads.stationId=s6586&amp;ads.ads_partner_alias=ceSonos&amp;ads.url=https%3a%2f%2ftunein.com%2fdesc%2fs6586%2f&amp;ads.description_url=https%3a%2f%2ftunein.com%2fdesc%2fs6586%2f&amp;ads.npa=1&amp;ads.gdfp_req=1&amp;ads.is_lat=1"/><CurrentTrackDuration val="0:00:00"/><CurrentTrackMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;res protocolInfo=&quot;sonos.com-http:*:audio/mpegurl:*&quot;&gt;x-sonosapi-stream:s6586?sid=254&amp;amp;flags=32&lt;/res&gt;&lt;r:streamContent&gt;&lt;/r:streamContent&gt;&lt;r:radioShowMd&gt;Bob,p1086126&lt;/r:radioShowMd&gt;&lt;upnp:albumArtURI&gt;/getaa?s=1&amp;amp;u=x-sonosapi-stream%3as6586%3fsid%3d254%26flags%3d32&lt;/upnp:albumArtURI&gt;&lt;dc:title&gt;x-sonosapi-stream:s6586?sid=254&amp;amp;flags=32&lt;/dc:title&gt;&lt;upnp:class&gt;object.item&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/><r:NextTrackURI val=""/><r:NextTrackMetaData val=""/><r:EnqueuedTransportURI val="x-sonosapi-stream:s6586?sid=254&amp;flags=32"/><r:EnqueuedTransportURIMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;dc:title&gt;OUI FM&lt;/dc:title&gt;&lt;upnp:class&gt;object.item.audioItem.audioBroadcast&lt;/upnp:class&gt;&lt;desc id=&quot;cdudn&quot; nameSpace=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot;&gt;SA_RINCONxxxxx_&lt;/desc&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/></InstanceID></Event>' (service 'AVTransport') for thing 'sonos:PLAY5:chambre'
2022-08-10 18:05:56.206 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'TransportState':'TRANSITIONING' (service 'AVTransport') for thing 'sonos:PLAY5:chambre'
2022-08-10 18:05:56.394 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'LastChange':'<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/"><InstanceID val="0"><TransportState val="PLAYING"/><CurrentPlayMode val="NORMAL"/><CurrentCrossfadeMode val="0"/><NumberOfTracks val="3"/><CurrentTrack val="1"/><CurrentSection val="0"/><CurrentTrackURI val="hls-radio://https://prod-pre.fns.tunein.com/v1/master/30ead7055f8b8e1f2f04add745f139b184df6925/prod_preroll/preroll0.m3u8?ads.cust_params=partnerId%253dSonos%2526ads_partner_alias%253dceSonos%2526version%253d57.12%2526premium%253dfalse%2526abtest%253d%2526language%253den-US%2526stationId%253ds6586%2526is_ondemand%253dfalse%2526genre_id%253dg54%2526class%253dmusic%2526is_family%253dfalse%2526is_mature%253dfalse%2526country_region_id%253d80%2526station_language%253dfrench%2526programId%253dp1086126%2526is_event%253dfalse&amp;ads.stationId=s6586&amp;ads.ads_partner_alias=ceSonos&amp;ads.url=https%3a%2f%2ftunein.com%2fdesc%2fs6586%2f&amp;ads.description_url=https%3a%2f%2ftunein.com%2fdesc%2fs6586%2f&amp;ads.npa=1&amp;ads.gdfp_req=1&amp;ads.is_lat=1"/><CurrentTrackDuration val="0:00:00"/><CurrentTrackMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;res protocolInfo=&quot;sonos.com-http:*:audio/mpegurl:*&quot;&gt;x-sonosapi-stream:s6586?sid=254&amp;amp;flags=32&lt;/res&gt;&lt;r:streamContent&gt;&lt;/r:streamContent&gt;&lt;r:radioShowMd&gt;Bob,p1086126&lt;/r:radioShowMd&gt;&lt;upnp:albumArtURI&gt;/getaa?s=1&amp;amp;u=x-sonosapi-stream%3as6586%3fsid%3d254%26flags%3d32&lt;/upnp:albumArtURI&gt;&lt;dc:title&gt;x-sonosapi-stream:s6586?sid=254&amp;amp;flags=32&lt;/dc:title&gt;&lt;upnp:class&gt;object.item&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/><r:NextTrackURI val=""/><r:NextTrackMetaData val=""/><r:EnqueuedTransportURI val="x-sonosapi-stream:s6586?sid=254&amp;flags=32"/><r:EnqueuedTransportURIMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;dc:title&gt;OUI FM&lt;/dc:title&gt;&lt;upnp:class&gt;object.item.audioItem.audioBroadcast&lt;/upnp:class&gt;&lt;desc id=&quot;cdudn&quot; nameSpace=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot;&gt;SA_RINCONxxxxx_&lt;/desc&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/></InstanceID></Event>' (service 'AVTransport') for thing 'sonos:PLAY5:chambre'
2022-08-10 18:05:56.528 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'TransportState':'PLAYING' (service 'AVTransport') for thing 'sonos:PLAY5:chambre'
2022-08-10 18:06:00.682 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'LastChange':'<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/"><InstanceID val="0"><TransportState val="PLAYING"/><CurrentPlayMode val="NORMAL"/><CurrentCrossfadeMode val="0"/><NumberOfTracks val="3"/><CurrentTrack val="2"/><CurrentSection val="0"/><CurrentTrackURI val="aac://http://ouifm.ice.infomaniak.ch/ouifm-high.aac"/><CurrentTrackDuration val="0:00:00"/><CurrentTrackMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;res protocolInfo=&quot;sonos.com-http:*:application/octet-stream:*&quot;&gt;x-sonosapi-stream:s6586?sid=254&amp;amp;flags=32&lt;/res&gt;&lt;r:streamContent&gt;&lt;/r:streamContent&gt;&lt;r:radioShowMd&gt;Bob,p1086126&lt;/r:radioShowMd&gt;&lt;upnp:albumArtURI&gt;/getaa?s=1&amp;amp;u=x-sonosapi-stream%3as6586%3fsid%3d254%26flags%3d32&lt;/upnp:albumArtURI&gt;&lt;dc:title&gt;x-sonosapi-stream:s6586?sid=254&amp;amp;flags=32&lt;/dc:title&gt;&lt;upnp:class&gt;object.item&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/><r:NextTrackURI val=""/><r:NextTrackMetaData val=""/><r:EnqueuedTransportURI val="x-sonosapi-stream:s6586?sid=254&amp;flags=32"/><r:EnqueuedTransportURIMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;true&quot;&gt;&lt;dc:title&gt;OUI FM&lt;/dc:title&gt;&lt;upnp:class&gt;object.item.audioItem.audioBroadcast&lt;/upnp:class&gt;&lt;desc id=&quot;cdudn&quot; nameSpace=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot;&gt;SA_RINCONxxxx_&lt;/desc&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/></InstanceID></Event>' (service 'AVTransport') for thing 'sonos:PLAY5:chambre'
2022-08-10 18:06:00.803 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'TransportState':'PLAYING' (service 'AVTransport') for thing 'sonos:PLAY5:chambre'

And this other command on the same period: egrep “PLAY|PAUSE|STOP” events.log

Here is the result in my case:

2022-08-10 18:05:54.206 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosChambreState' changed from PLAYING to TRANSITIONING
2022-08-10 18:05:54.210 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosChambreControl' changed from PLAY to UNDEF
2022-08-10 18:05:54.478 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosBureauState' changed from PLAYING to STOPPED
2022-08-10 18:05:54.488 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosBureauControl' changed from PLAY to PAUSE
2022-08-10 18:05:54.546 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosBureauState' changed from STOPPED to TRANSITIONING
2022-08-10 18:05:54.553 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosChambreState' changed from TRANSITIONING to STOPPED
2022-08-10 18:05:54.556 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosChambreControl' changed from UNDEF to PAUSE
2022-08-10 18:05:54.561 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosBureauControl' changed from PAUSE to UNDEF
2022-08-10 18:05:54.615 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosChambreState' changed from STOPPED to TRANSITIONING
2022-08-10 18:05:54.617 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosChambreControl' changed from PAUSE to UNDEF
2022-08-10 18:05:54.635 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosBureauState' changed from TRANSITIONING to STOPPED
2022-08-10 18:05:54.639 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosBureauControl' changed from UNDEF to PAUSE
2022-08-10 18:05:54.700 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosBureauState' changed from STOPPED to TRANSITIONING
2022-08-10 18:05:54.706 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosBureauControl' changed from PAUSE to UNDEF
2022-08-10 18:05:56.535 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosChambreState' changed from TRANSITIONING to PLAYING
2022-08-10 18:05:56.538 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosChambreControl' changed from UNDEF to PLAY
2022-08-10 18:08:56.330 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosBureauState' changed from TRANSITIONING to STOPPED
2022-08-10 18:08:56.332 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SonosBureauControl' changed from UNDEF to PAUSE

This might a timing issue, something not run in the same order in your case.

Note that I was able to reproduce a case where the ungrouped device remains in state TRANSITIONING (and not STOPPED), but this is not what you mention.

In fact, I realize that my log example shows the case I mentioned (not expected result) but this is not the same case as yours ! The state is set to TRANSITIONING and finally to STOPPED only 3 minutes later.

In the case I reproduced, this looks clearly something strange on the Sonos device which keeps a TRANSITIONING state during 3 minutes.
Edit: I believe it could be caused by the binding.

That being said, maybe I should change the handling of this state TRANSITIONING, meaning trigger no change on channels state.

I don’t think I’m filtering this correctly because it is so long, but here is the output with TRACE org.openhab.binding.sonos enabled, TransportState from openhab.log. This is specifically for the event of step 5 only:

new 1.txt (97.0 KB)
I note that there is a lot of chatter from other sonos devices, which appears to be happening all the time. To be clear, no other speakers were playing anything or grouped during this interaction, just “Conservatory” and “Kitchen”. Not sure why there is so much going on here.

And here is “PLAY|PAUSE|STOP” from events.log

2022-08-10 18:24:23.905 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'c_sonos_control' changed from PAUSE to PLAY
2022-08-10 18:25:01.443 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'k_sonos_control' changed from UNDEF to PLAY
2022-08-10 18:25:01.457 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'c_sonos_control' changed from UNDEF to PLAY
2022-08-10 18:25:43.168 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'k_sonos_control' changed from PAUSE to PLAY
2022-08-10 18:33:21.429 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'c_sonos_control' changed from PAUSE to PLAY
2022-08-10 18:33:26.099 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'k_sonos_control' changed from UNDEF to PLAY
2022-08-10 18:33:26.110 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'c_sonos_control' changed from UNDEF to PLAY
2022-08-10 18:34:37.936 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'k_sonos_control' changed from PAUSE to PLAY

I submitted a change to ignore the TRANSITIONING state. It apparently solved the issue I encountered. Maybe it will solve yours too. Can you please try the jar file provided with the PR ?

In your logs, at the end I see the last handled TransportState is PLAYING for ‘sonos:One:kitchen’ and PAUSED_PLAYBACK for ‘sonos:One:conservatory’. It lloks good, no ?
Or maybe the problem was not your last action and so not at the end of the logs ? Can you provide the timing ?

That has immediately fixed it. So far I’ve tested both ways (each of these two speakers being ingrouped as localcoordinator) and everything is reflected accurately in openHAB.

Amazing, thanks for looking into it! Will this be merged at some point or might this new approach break something else?

Not that it matters now you’ve discovered the issue, but the the end result in my logs should have been that the Kitchen stopped playing and Conservatory continued so it was still incorrect.

I’m dropping it in also.

Best, Jay

As this is only 7 new lines of code, I hope this will be merged very soon. It could be part of 3.4 Milestone 1 coming soon.
This change should break nothing.

1 Like

Fix was merged, so will definitely be part of the upcoming Milestone, which is scheduled for the next days.

1 Like