Awesome!
0.7.1 Up... only change is trying to catch an issue some people see on the websocket message parse regarding a null object.
1 Like
i always get this on start up of the hub
if i disable it and re enable it it will be fine. So its as if the hub starting up makes it do something that runs away
1 Like
Hmm. I wonder if somehow it’s getting tossed in a loop for a bit. If it’s not too much bother, could you turn on all logging, debug and trace level, then send me the first minute or two worth of logs from a speaker that’s going haywire? There’s a bunch of cooldowns already in the code that should keep it from going too crazy, but maybe there’s someway that it’s not getting limited properly.
Than said every reboot on my hub causes a huge spike of activity, from a ton of stuff not just Sonos Advanced. Though Sonos Advanced is certainly the heaviest thing causing the spike. Initialize() does a ton of stuff so having it run for every speaker at once is definitely going to cause a big spike.
Maybe I need to put a semaphore in initialize to keep more than one speaker from running it at the same time.
Logs would be super helpful in figuring out. PM them if you can, thanks!
2 Likes
Might be a good idea especially people with a big systems.
No worries just doing some z-wave stuff right now once i have done ill turn them all on and shutdown again and repower and see what i get then message you.
1 Like
I'm getting severe hub load alerts again on the latest version. Just noticed none of my sensors were turning on lights around the house, attempted to access HE and it was unresponsive. Unplugged power and restarted HE and within 2 minutes the device page hit 360% total with my 5 Sonos speakers on ~20% each and a severe load alert. Disabling the 5 speakers made it stable again.
Weirdly there's no warnings/errors in the logs.
I'll re-enable the devices and keep an eye on it.
0.7.2 out on HPM.
Changes are just adding a bunch of logic around when and how to subscribe/resubscribe. It seems a few people were getting tossed into a loop somehow, especially after a reboot where it would just subscribe over and over rather than "settling down" after a minute.
Full changes include adding semaphores around each of the subscription methods so multiple threads can't attempt to subscribe at the same time for the same device and end up in a spot where a second thread overwrites the first's subscription. There's also more logic for determining "is this already subscribed" so it shouldn't even try to subscribe unless it needs to, for both the UPnP subscriptions and the websocket ones.
Tested new logic for over 12 hours on both my C7 and C8-Pro and everything seems good. On hub reboot there's still a CPU spike as expected since it needs to run through everything and make sure it's subscribed, but the logs only show it doing each subscription once and not looping or doing the same subscription repeatedly.
My C7 reports around 7 minutes of CPU time used at reboot... and I'm sure that's fake news:
Even IF this is totaling all 4 CPU cores, ie, on a 4 core CPU at 100% usage it would be 400%, it doesn't make sense to see 592%...
No idea how this could possibly tally up to nearly 600%... The only thought I can think is it's somehow counting all the time where a thread is sleeping while waiting on async IO or something. But counting a sleeping thread waiting on async IO as "using CPU processor seconds" is completely the wrong thing to do.
Anyway, just completely ignore whatever number you see here right after a reboot, it's lying to you.
2 Likes
feature request
the play text and restore only appears under capability "music player" but the group device does not appear under that option, otherwise we have to use custom attributes each time.
Edit:
maybe it's not there for a reason now looking at it?
Adding Music Player brings a bunch of other baggage with it:
It's all or nothing. So I'd have to implement all of those onto the group devices.
Not particularly hard, since I could just make them another "follower", but then they'd also have all the state that goes along with it, and more importantly, they'd end up taking up more CPU raising all the events that come along too.
If you have a whole bunch of groups, right now they use almost no CPU. But adding Music Player would increase that a fair bit.
At some point once I have all of the Shelly drivers I'm working on and a few other things wrapped up I could visit the idea of expanding the group devices like this, but I'd need to implement all of it, then do some testing to make sure it doesn't blow up the CPU usage.
There's also the trouble of getting all of the events needed for Music Player from the coordinator to the group devices.
3 Likes
I had second thoughts as soon as I posted it 
so no worries it was me being lazy and not thinking it fully through.
1 Like
After reboot no flags and devices are high in the list but within normal expected so it's looking good.
I will do a shut down and start at some point to fully check.
With the latest update, I've observed the individual speaker volumes are not updated as adjustments are made, and instead reflect a fixed value that mirrors the state restoreLevelafterMute. The GroupVolume, whether the speaker is primary, secondary, or ungrouped, updates with every adjustment.
I tried enabling more logging, but didn't see any events for volume adjustments to individual speakers.
As I missed a few updates while traveling, perhaps this has been true for a while or there has been some discussion why this is so. Thanks.
EDIT: I should clarify that I first noticed this behavior yesterday, but after a hub reboot it appeared to be working normally. This morning, however, the volumes are 'stuck" again.
I've been having issues recently with my C7 locking up. I only have Lan/WiFi/Cloud integrations active on the hub.
I've narrowed it down to 2 apps, I think, which I have enabled full logging on.
Device 11311 is one of my sonos devices that is the primary device in a group of 2 devices.
I've just had a mass of errors come in from this app but as yet the hub has not locked up. Any thoughts?
app errors
[app:12652](http://192.168.0.24/logs#)2024-03-04 15:38:37.764[error](http://192.168.0.24/logs#)com.hubitat.app.exception.LimitExceededException: Device 11311 generates excessive hub load on line 2465 (method sendEvent)
[app:12652](http://192.168.0.24/logs#)2024-03-04 15:38:37.463[error](http://192.168.0.24/logs#)com.hubitat.app.exception.LimitExceededException: Device 11311 generates excessive hub load on line 2465 (method sendEvent)
[app:12652](http://192.168.0.24/logs#)2024-03-04 15:38:37.128[error](http://192.168.0.24/logs#)com.hubitat.app.exception.LimitExceededException: Device 11311 generates excessive hub load on line 2465 (method sendEvent)
[app:12652](http://192.168.0.24/logs#)2024-03-04 15:38:36.810[error](http://192.168.0.24/logs#)com.hubitat.app.exception.LimitExceededException: Device 11311 generates excessive hub load on line 2465 (method sendEvent)
[app:12652](http://192.168.0.24/logs#)2024-03-04 15:38:36.442[error](http://192.168.0.24/logs#)com.hubitat.app.exception.LimitExceededException: Device 11311 generates excessive hub load on line 2465 (method sendEvent)
[app:12652](http://192.168.0.24/logs#)2024-03-04 15:38:36.123[error](http://192.168.0.24/logs#)com.hubitat.app.exception.LimitExceededException: Device 11311 generates excessive hub load on line 2465 (method sendEvent)
[app:12652](http://192.168.0.24/logs#)2024-03-04 15:38:35.733[error](http://192.168.0.24/logs#)com.hubitat.app.exception.LimitExceededException: Device 11311 generates excessive hub load on line 2465 (method sendEvent)
[app:12652](http://192.168.0.24/logs#)2024-03-04 15:38:35.359[error](http://192.168.0.24/logs#)com.hubitat.app.exception.LimitExceededException: Device 11311 generates excessive hub load on line 2465 (method sendEvent)
[app:12652](http://192.168.0.24/logs#)2024-03-04 15:38:35.044[error](http://192.168.0.24/logs#)com.hubitat.app.exception.LimitExceededException: Device 11311 generates excessive hub load on line 2465 (method sendEvent)
I'm also seeing lots of warnings in the logs for the primary device.
Here's a snippet.
Device warnings
[dev:11311](http://192.168.0.24/logs#)2024-03-04 15:54:35.014[warn](http://192.168.0.24/logs#)Sonos Advanced - Living Room: parse() ran into an issue: java.lang.ArrayIndexOutOfBoundsException: Index 1 out of bounds for length 1
[dev:11311](http://192.168.0.24/logs#)2024-03-04 15:54:34.989[warn](http://192.168.0.24/logs#)Sonos Advanced - Living Room: JSON from failed websocket parse: [{"namespace":"groups","householdId":"Sonos_xaeR71IEpgTHcUqVMYasXemhmM.h0QjSikDR4W32pLJ6qV3","locationId":"lc_4bafb55fa6e34f2da19bbaafc798922d","name":"groups","type":"groups"},{"_objectType":"groups","groups":[{"_objectType":"group","id":"RINCON_B8E937DCA93401400:77","name":"Living Room + 1","coordinatorId":"RINCON_B8E937DCA93401400","playerIds":["RINCON_B8E937DCA93401400","RINCON_5CAAFD2D843E01400"]}],"players":[{"_objectType":"player","id":"RINCON_B8E937DCA93401400","name":"Living Room","websocketUrl":"wss:\/\/192.168.0.16:1443\/websocket\/api","softwareVersion":"77.4-49290","apiVersion":"1.38.0","minApiVersion":"1.1.0","isUnregistered":false,"capabilities":["CLOUD","PLAYBACK","AUDIO_CLIP"],"zoneInfo":{"_objectType":"activeZone","name":"Living Room","members":[{"_objectType":"activeZoneMember","id":"RINCON_B8E937DCA93401400","channelMap":[],"state":{"_objectType":"zoneMemberState","disconnected":false}}]},"deviceIds":["RINCON_B8E937DCA93401400"],"devices":[{"_objectType":"deviceInfo","id":"RINCON_B8E937DCA93401400","serialNumber":"B8-E9-37-DC-A9-34:3","model":"S3","modelDisplayName":"Play:3","capabilities":["CLOUD","PLAYBACK","AUDIO_CLIP"],"deviceFeatures":[{"_objectType":"feature","name":"WIFI"},{"_objectType":"feature","name":"ETHERNET"},{"_objectType":"feature","name":"WIFI_2GHZ"},{"_objectType":"feature","name":"WIFI_5GHZ"},{"_objectType":"feature","name":"BUTTON_VOL_ROCKER"},{"_objectType":"feature","name":"BUTTON_MUTE"},{"_objectType":"feature","name":"LACKS_HI_RES_MUSIC"},{"_objectType":"feature","name":"MUST_PAUSE_FOR_AUDIOCLIP"},{"_objectType":"feature","name":"EQ_COLLECTION"},{"_objectType":"feature","name":"LED_MUTE"},{"_objectType":"feature","name":"WIRELESS_SONOSNET"},{"_objectType":"feature","name":"CONTROLLER_CFG_SATELLITE"},{"_objectType":"feature","name":"LED_STATUS"},{"_objectType":"feature","name":"DUALBAND_STATION"},{"_objectType":"feature","name":"STEREO_PAIR"},{"_objectType":"feature","name":"EQ_BALANCE"}],"apiVersion":"1.38.0","minApiVersion":"1.1.0","name":"Living Room","websocketUrl":"wss:\/\/192.168.0.16:1443\/websocket\/api","softwareVersion":"77.4-49290","hwVersion":"1.8.1.3-2.0","swGen":2,"quarantineReasons":[]}]},{"_objectType":"player","id":"RINCON_5CAAFD2D843E01400","name":"Portable","websocketUrl":"wss:\/\/192.168.0.33:1443\/websocket\/api","softwareVersion":"77.4-49290","apiVersion":"1.38.0","minApiVersion":"1.1.0","isUnregistered":false,"capabilities":["CLOUD","PLAYBACK","AUDIO_CLIP"],"zoneInfo":{"_objectType":"activeZone","name":"Portable","members":[{"_objectType":"activeZoneMember","id":"RINCON_5CAAFD2D843E01400","channelMap":[],"state":{"_objectType":"zoneMemberState","disconnected":false}}]},"deviceIds":["RINCON_5CAAFD2D843E01400"],"devices":[{"_objectType":"deviceInfo","id":"RINCON_5CAAFD2D843E01400","serialNumber":"5C-AA-FD-2D-84-3E:G","model":"S1","modelDisplayName":"Play:1","capabilities":["CLOUD","PLAYBACK","AUDIO_CLIP"],"deviceFeatures":[{"_objectType":"feature","name":"WIFI"},{"_objectType":"feature","name":"ETHERNET"},{"_objectType":"feature","name":"WIFI_2GHZ"},{"_objectType":"feature","name":"WIFI_5GHZ"},{"_objectType":"feature","name":"BUTTON_PLAY_PAUSE"},{"_objectType":"feature","name":"BUTTON_VOL_ROCKER"},{"_objectType":"feature","name":"MONO_SPEAKER"},{"_objectType":"feature","name":"LACKS_HI_RES_MUSIC"},{"_objectType":"feature","name":"MUST_PAUSE_FOR_AUDIOCLIP"},{"_objectType":"feature","name":"EQ_COLLECTION"},{"_objectType":"feature","name":"WIRELESS_SONOSNET"},{"_objectType":"feature","name":"CONTROLLER_CFG_SATELLITE"},{"_objectType":"feature","name":"LED_STATUS"},{"_objectType":"feature","name":"DUALBAND_STATION"},{"_objectType":"feature","name":"STEREO_PAIR"}],"apiVersion":"1.38.0","minApiVersion":"1.1.0","name":"Portable","websocketUrl":"wss:\/\/192.168.0.33:1443\/websocket\/api","softwareVersion":"77.4-49290","hwVersion":"1.8.3.7-2.0","swGen":2,"quarantineReasons":[]}]}],"partial":false}]
[dev:11311](http://192.168.0.24/logs#)2024-03-04 15:54:34.804[warn](http://192.168.0.24/logs#)Sonos Advanced - Living Room: Ran into an issue parsing websocket: com.hubitat.app.exception.LimitExceededException: Device 11311 generates excessive hub load
EDIT: While this was happening I got an alert on the hub for 'Excessive Load' so I'm assuming this is causing my lockup issues.
I've currently disabled the app and devices.
7.1 was running great... updated to 7.2 yesterday with the newer semaphore logic and it crashed the hub again...
had to manually roll back to 7.1 by using code on another hub (couldn't find 7.1 on your gitgub.)
@daniel.winks
Hi Daniel,
I'm not sure if you've had a chance to look at this or missed it, but have you any thoughts on these errors?
I disabled the app and devices yesterday and the hub is now running fine.
Maybe I need to completely remove and start again, which I'm happy to do, but thought I'd wait in case there is any further information you may need.
Thanks.
I put in 0.7.3 that removed the debounce from the WS stuff. Not sure if that's the root cause here since I'm not seeing this issue on either of my hubs. But everything in this log is websocket-related, and adding a debounce it the subscribe is the only major change between 0.7.1 and 0.7.2. There's also a a check to see whether or not the speaker is already currently subscribed and to skip subscribing if it is.
When you subscribe to anything on Sonos it responds with a bunch of data. That data contains information that is needed to determine whether to do other things. So you sub to zonegrouptopology or websocket groups and that gives you information about the current group layout. Depending on what's in that will determine whether or not a speaker is a coordinator or follower, and based on that other subscriptions are needed to be sub or unsub to.
Now they're mostly connected but there really shouldn't be a loop. ZGT sends back which speaker is coordinator and which are followers, and that determines whether or not to subscribe to AVT and playback/playbackMetadata, but AVT/playback in no way influences whether or not to subscribe to ZGT, as the speakers are always subscribed to ZGT. So there really shouldn't be loops, but other than subscription loops I can't see how any of this would run for 120+ seconds.
You could also try setting "singleThreaded: false" at the top of the player driver to "true" if 0.7.3 causes issues still and see if that clears it up. But that also means I'm back to having a single thread trying to handle all the incoming messages which I think was part of the problem with it taking too much time before.
It's just lame since almost all of these issues are just "what the F is the underlying Groovy runtime on Hubitat actually DOING?!" rather than issues with my code. Well, it might be some weird thing my code causes, but with no insight into what is actually happening, it's nearly impossible to tell, as the 4? 5? near total re-writes of Sonos Advanced shows. Things are fine on my hubs, I release it and someone has 120+ second timeouts. Rewrite huge portion of code and then someone else has them. It's like blindfolded whack-a-mole and it's not fun.
5 Likes
FWIW, I haven't seen any errors logged or experienced any excessive load warnings or hub crashes since either the 0.7.1 or 0.7.2 updates, despite having a larger system, although there are at least one or two users (if not several) whose systems are much larger still.
The issue with the individual device volume attribute not updating is still present with 0.7.3. This one baffles me a little bit, as it works for a while following a hub reboot or app update, then gets "stuck" and stops recognizing volume changes. The other device attributes including groupVolume, audioTrackData, status (and transportStatus), and are still responsive. As yet, I haven't seen any errors or other log data to help me pin down a time or event that is causing this problem. Any suggestions?
Thank you. Updated to 7.3 and fingers crossed... 
I decided to do this and everything is working OK.
Something had obviously got corrupted somehow. 
Yeah, I'll probably add that at some point. It'll require adding a whole new UI screen, and the UI screen code in Hubitat is probably my least favorite thing to deal with.
But why bother with the Sonos on an IoT VLAN? I get tossing some random Chinese WiFi bulbs on there. I understand why people put KNOWN HOSTILE Chinese IP webcams on them, but personally I think that's like letting a burglar into your house "but keeping an eye on them". When it comes to crap like Chinese IP cams I think the only place for them is the trash, not a VLAN... but Sonos? They're trustworthy. I can tell you, having ran Wireshark for hours and days on these speakers to reverse engineer things for Sonos Advanced that they aren't doing anything unexpected. I trust them at least as much as I trust my iPhone and MacBook.
I suspect that, like pretty much everything with UniFi, your SSDP relay doesn't work right. I sold all my UniFi stuff after years of dealing with their bugs, broken promises, half-baked features, and all around crappiness. If SSDP worked properly, Sonos Advanced would see the speakers. Ubiquiti is great at making a fancy website and shiny UI, but their hardware/firmware is horribly lacking.
I'm betting the official Sonos app uses mDNS for discovery, which must actually work on UniFi. My app and the built-in one on Hubitat both use SSDP. I asked/pestered @gopher.ny about mDNS and he said he was putting it in on the next beta (the one coming out next). So if that happens once it's on the stable version of Hubitat I can update my app to use mDNS instead of/in addition to SSDP. This should work just like the official Sonos app then and should work with buggy UniFi gear.
4 Likes
