Announcement

**dcorsus** · January 2, 2019, 11:24 AM

Originally posted by xs10shl View Post

Firstly, let me say thanks for providing this free plugin. I've had some issues with using it, which I can't say are related to other problems I've seen posted, so I;m posting them on the hope that we can discover the root cause, and stabilize the Plugin. Apologies in advance for the lengthy post - I just wanted to expose or get past any potential configuration errors with as few back and forth posts as possible.

I'm running your latest released plugin, 3.1.0.26 on Win7/64,HS3 Pro Edition 3.0.0.478, installed using HS installer, firewall off, MusicDB regularly sync'd
I have 3 Sonos Connects running the latest software/firmware.

What I'm describing is happening on a fresh install with newly updated SonosDB using BuildDB, and firewall off.

There are certain playlist-selection paths which cause the plugins to freeze or not update all but a few device status fields when I execute certain radiostations and podcasts. This happens whether or not I use the plugin GUI to select the item, or if I select it from the My Sonos page, or if I make the selection from the Sonos app on my iiPhone. The selected items will play through the speakers, and the Sonos App is updated appropriately, but the PI stops updating its status. Sometimes I can get it to recover by selecting a known radtiostation or playlist that I know the PI will respond well to.

Other things, such as Albums, playlists of songs, and Pandora radio stations appear to work reliably. Also, even on a frozen metadata screen, the control buttons still work. Another symptom is that it's slightly more likely to happen if I select an item from My Sonos page to play, vs if I select it by browsing and selecting from within the app for the exact same content (but that may be anecdotal information - I have not exhaustively confirmed that last piece of info)

At any rate, I attempted a complete reinstall (Plugin Disabled, fresh download/install using HS installer, HS3 shutdown, Delete Sonos.ini and MusicDB. Restart HS, Sonos systems rediscovered/ BuildDB executed). Even after doing this, I can reliably get the PI to freeze and stop updating it's status almost immedialtely upon attempting to play some selected podcasts.

BTW, these podcasts are derived from Google Music, if the source matters. your URI in the SonosDB starts with x-rincon-cpcontainer for all the podcasts.

A few caveats: I do sometimes change the names of some of the Songs, Playlists and Podcasts on the My Sonos page. I've verified that these changes are carried down to the SonosDB on Sync. If I make changes to the name of Pandora Radio stations (and sync the SonosDB) the system does work as it should, so I assume that such a name change should not pose a problem per say. I've verified that certain Podcasts cause the PI to freeze regardless of whether or not I've changed the name in My Sonos, or whether I select them from the My Sonos page or from within the Sonos App.

I tried looking for your latest beta but could not find it in the Beta section in the Installer.

Happy to provide any logs you would like if you feel like this is a PI issue. Just let me know what debug level you'd like me to set them to.

Thanks in advance!

How is your "update music DB" settings? Can you post a screen shot of the config page? Is the "update music DB" set to immediate? If so, set it to daily at say 2am. If you have a lot of DB changes, the PI can get very busy to create the DB and is VERY processor intensive, perhaps a reason why the PI is sluggish.
If not that, do you see errors in the log?
If not, perhaps turn on the debug flag, turn the log to disk flag on, do what isn't working, turn log to disk off, post log file (<hs root>\html\Sonos\Logs)

**xs10shl** · January 3, 2019, 09:28 PM

Update music settings:
Auto Update =True (2:10 AM from First Sonos System)
Immediate Update = False
ipod Update = false

Logfile is clear of errors.

Using SQLiteStudio I can confirm everything is there before running any tests.

As A test:
- I issue a manual BuildDB call (and verify it's in DB)
- Load a google play Podcast Freakonomics - Sometimes the image loads
- Sometimes right then, but sometimes on the next or third selection, things go south.
- All buttons work, but no device status is updated from the point of status loss onwards
- If I hit the PI 'Next' button. the next Freakonomics Podcast starts playing, Sonos App on iPhone Updated, PI remains frozen
- If I select something I know the PI will not cause the PI to freeze, like a Pandora Radiostation, things may recover, but not always.
- PI usually updates with new content about 5-10 seconds in to new selection, and will work until another Podcast is selected as above

Behavior is variable. Sometimes it will freeze for minutes, sometimes it works. But I can always get it to freeze by the 3rd or 4th selection.

I made a video of some of the unsync'd behavior and will post a link. In it you'll see the player status get out of sync, and status and artwork not update for the Google Play podcasts. I'm doing a side-by-side video with Sonos on the iPad so we can see what is happening on the Sonos side of things. Perhaps it's a timing issue? Your PI gets out of sync with the status of the Sonos Controller, and when there's a delay in refreshing the content from Sonos, perhaps the PI misses it completely? After it misses once, it tends to be unable to recover until it plays something it can deal with. the things I'm sending to "reset to normal" are all listed as "Radiostation" calls in the SonosDB, which I believe you handle slightly differently.

Note: I have not tested all permutations, to see what works and what doesn't.

Video link below. This is a crap video, but if you look carefully you can see that after the third selection. the button status is out of sync with the Sonos App below, and the Title stops updating until I select something that isn't a podcast.

https://www.youtube.com/watch?v=_BXBA3ttSL4

I'll get you some log files.

**xs10shl** · January 3, 2019, 10:50 PM

This next video and accompanying log file shows the behavior while selecting Podcasts to play on the Sonos App, and the corresponding behavior on the PI. The log file should by synced fairly well with the action on the Video. As you can see, the PI starts frozen on Mad Money, - a selection I made 10 minutes ago before grabbing a slice of pizza (to rule out any latency), and remains frozen for a good part of all the selections, until a call to load the latest podcast of Freakonomics is made when it pseudo-recovers. Then it freezes on that selection for the rest of the video, including status updates. These are not SonosDB selections, but rather podcast stream selections that I'm making through the Sonos App. I would have thought that they would update in the PI, so I surmise that there is some sort of sync problem going on.

Logfile attached. Accompanying video at:
https://www.youtube.com/watch?v=qY5BTppvxxM

Just a data point. I just restarted HS after uploading these files, and the plugin still thinks I'm on Freakonomics Radio, even though other sources are playing

Attached Files

SonosDebug.txt (233.6 KB, 0 views)

**dcorsus** · January 3, 2019, 10:55 PM

Originally posted by xs10shl View Post

This next video and accompanying log file shows the behavior while selecting Podcasts to play on the Sonos App, and the corresponding behavior on the PI. The log file should by synced fairly well with the action on the Video. As you can see, the PI starts frozen on Mad Money, - a selection I made 10 minutes ago before grabbing a slice of pizza (to rule out any latency), and remains frozen for a good part of all the selections, until a call to load the latest podcast of Freakonomics is made when it pseudo-recovers. Then it freezes on that selection for the rest of the video, including status updates. These are not SonosDB selections, but rather podcast stream selections that I'm making through the Sonos App. I would have thought that they would update in the PI, so I surmise that there is some sort of sync problem going on.

Logfile attached. Accompanying video at:
https://www.youtube.com/watch?v=qY5BTppvxxM

Just a data point. I just restarted HS after uploading these files, and the plugin still thinks I'm on Freakonomics Radio, even though other sources are playing

could you take this log with ONLY debug flag on, UPNP logging to error only and superdebug Off (and log to disk :-))

**xs10shl** · January 3, 2019, 10:59 PM

Config page attached (after I turned off logging)

Attached Files

**xs10shl** · January 3, 2019, 11:43 PM

Ok DuperBebug off. This one has a bunch of changes to various podcasts- a different different path of execution to the last video. The PI was frozen on Freakonomics till about half way through, so I dont have an idea about whether you are seeing all the events that happened before the PI starts responding to the changes I'm making on the sonos App. It does freeze up again intermittently, so hopefully there is some data you can use. If everything looks like its working in your log file, then I'll redo a video where you can see the button presses I'm making on the Sonos app, to verify that the PI is not detecting the status updates.

Attached Files

SonosDebug.txt (92.1 KB, 0 views)

**xs10shl** · January 4, 2019, 12:34 AM

Also to note, in case it comes up - everything on the same wired subnet - the same switch as the Sonos Connects - running on a development laptop wtih 4GB memory and 1TB SSD. CPU cycles rarely above 5%, and HS is the only app running. I do have a a two plugins which register callbacks with HS - there is a lag on startup when everything is initializing, which is to be expected. There are a total of 537 devices in the HS database. The web Device screen refresh can take up to 1 or two seconds to update over the internet, but I'm detecting everything from event-driven scripts, which are much more responsive. For Playlists that don't freeze the PI, the script call is very quick- as fast as the Sonos App updates on my iPhone.

**dcorsus** · January 4, 2019, 12:51 AM

Originally posted by xs10shl View Post

Ok DuperBebug off. This one has a bunch of changes to various podcasts- a different different path of execution to the last video. The PI was frozen on Freakonomics till about half way through, so I dont have an idea about whether you are seeing all the events that happened before the PI starts responding to the changes I'm making on the sonos App. It does freeze up again intermittently, so hopefully there is some data you can use. If everything looks like its working in your log file, then I'll redo a video where you can see the button presses I'm making on the Sonos app, to verify that the PI is not detecting the status updates.

Don't really see anything wrong but there is an error about deleting artwork that intrigues me. What platform is this running on? Is this a VM or something special. Moreover, what antivirus is installed?
If you go to <hs root>\html\sonos\artwork what do you see in that directory? Plenty of files?
In the above log, when you say: "frozen", what does that mean? Are you looking at the player page?

**dcorsus** · January 4, 2019, 12:59 AM

Originally posted by xs10shl View Post

Also to note, in case it comes up - everything on the same wired subnet - the same switch as the Sonos Connects - running on a development laptop wtih 4GB memory and 1TB SSD. CPU cycles rarely above 5%, and HS is the only app running. I do have a a two plugins which register callbacks with HS - there is a lag on startup when everything is initializing, which is to be expected. There are a total of 537 devices in the HS database. The web Device screen refresh can take up to 1 or two seconds to update over the internet, but I'm detecting everything from event-driven scripts, which are much more responsive. For Playlists that don't freeze the PI, the script call is very quick- as fast as the Sonos App updates on my iPhone.

Hadn't seen this posting when I posted the previous set of questions. I do need some clarifications:
a/ you write "I do have a a two plugins which register callbacks", can you clarify that statement
b/ Why is it expected there is a lag at init?
c/ Can you elaborate what event-driven scripts are? I'm still trying to rule out this is not an AJAX webpage update issue over a PI issue

**xs10shl** · January 4, 2019, 03:56 AM

System: Platform is win7/64. No Antivirus, firewall off, HS running as Administrator.

Artwork subdir does not exist in html/Sonos directory. I just did a reinstall to verify problems before reporting my issues, so I cant say why it's missing, unless I randomly deleted it. I manually added it with full privileges. Did a an HS restart as administrator twice after creating the folder. Behavior remains the same as described before. interestingly, no artwork is being placed in the folder, even when the plugin is updating status properly.

I'll try to be as succinct as possible in my descriptions below, so they may be a tad wordy and redundant only to attempt to convey as much information to you as possible. I thought the videos did a pretty fair job of showing the symptoms, and I can make another one if it could help.

"Frozen" is to mean - Artwork, Track, Track Position, State and Radiostation are no longer syncing with the Sonos Connect. The buttons work as expected, but no metadata is reported as having been changed. For example, in the log file I gave you, I was making changes to Sonos queue using the Sonos App on my iPhone (not the PI), and the PI was not updating to reflect the status changes. This happens primarily when attempt to listen to a Podcast on GooglePlay. It does not happen when I listen to a radiotstation on Pandora, or if I play anything on Spotify. I can't say why it appears to be music source dependent. I can purposely put the PI into a "frozen" state (as I described before) if I call up a GooglePlay Podcast on either a Sonos App in iPhone, or if I select it using your plugin player. Very odd.

a) two plugins are easytrigger and a Lutron lighting plugin. I'm working to remove easytrigger from my code, down to just one callback, (I'm assuming that's how these are written). I disabled them and restarted HS. The Sonos freeze remains as described when I play my GooglePlay Podcasts, so I don't think thats the problem.

b) I expected a lag because lutron plugin registers a bunch of device notifications on startup.I don't know how it's written, but I'd venture to say it's not a super-efficient startup procedure. It is launched first by HS, so other plugins wait for it to finish. Once it completes, the Sonos plugins are loaded, and report that they have initialized properly. Disabling the other plugins made everything load a little faster, but the symptoms remained.

c) My event-driven scripts are called principally for Sonos PI status change on "Track" and "Player" status changes,

Track Event Trigger: The only event trigger for track is 'When Sonos Track is set or changed", which runs a single instance script of 15 lines of code that reads the track title and sends it off to a keypad, and exit. This works extremely reliably unless I call up a GooglePlay Podcast, at which point the plugin Track status freezes, causing the event to not trigger, and metadata updates to the keypad to not happen. The track has been changed to the new Podcast selection and is playing, so the user sees the old metadata on the keypad, while hearing the new podcast.

Player Event Triggers: The events "When Sonos events - player Paused" and "When Sonos events - player starts playing" also call short scripts which send status events, and work reliably during the times that the system track status freezes.

Previous Manual Triggers which caused similar problems: I at one point had sonos.Action nextRadiotstation and sonos.Action prevRadiostation events that I would trigger manually from my control panel, and they tended to work about the first 4 or 5 times, and then also cause freezes as described above. These were not critical features, so I removed the feature. It's possible that it would freeze upon arriving at a GoogePlay station, which I did have isprinkled in the RadiostationsDB, but that is just speculation.

Thank you very much for looking into this. I hope I can provide you with enough information so that we can resolve the situation. For now, the workaround is "Dont listen to GooglePlay Podcasts". I will attempt to see if I can play the same podcasts from other services next, and report back.

**xs10shl** · January 4, 2019, 04:05 AM

A Little more info. Just now, In playing another Podcast from GooglePlay, it will play over the speakers, but the PI shoved it into the "Play Next" status field, instead of updating the Track field. Very odd, I'll see if I can reliably duplicate that condition.

**dcorsus** · January 4, 2019, 12:01 PM

Originally posted by xs10shl View Post

A Little more info. Just now, In playing another Podcast from GooglePlay, it will play over the speakers, but the PI shoved it into the "Play Next" status field, instead of updating the Track field. Very odd, I'll see if I can reliably duplicate that condition.

I looked at your last posting one more time, deleted out a bunch of non-related stuff and analyzed it very closely. I don't see anything wrong.
I do see a few times you cycling between pause, play, stopped of a Jim Cramer podcast; then it switches to Ben Greenfield fitness. All seem to reaction properly, I see no delays at all, I see HS devices and state being updated when they are supposed to ....

Just as an FYI; these are stations that "stream" and they "buffer" so there is a lag between Sonos announcing the change and the actual PLAY state. Sonos uses "transition" state events to indicate the user has selected new content but the content is not playing yet. The PI ignores transition events else you would end up with multiple triggers for the same track change event.

One way to observe this is to look at the HS logging screen and set a filter (and obviously select dynamic updating of the screen). Filter for example on "PlayChangeNotifyCallback" or "CurrentPlayerState" or "(title)" and now observe your controller screen and the log entry appearing. Do they lag severely (think more than a second or 2), not show up at all or they are there?

As to the art error, I think I may have mis-typed the correct path. It should be <hs root>\html\images\sonos\artwork. I don't think it has anything to do with it however, one potential issue could be that when a track changes, the PI receives the new art-url info, tries to retrieve it, if that takes say seconds or ends up timing out, this could explain jittery behavior. However, I actually don't see any art info being provided in the first place and I think the PI is just writing the default art image.

Dirk

**xs10shl** · January 4, 2019, 08:32 PM

Intersting - the times you could see me cycling on the Jim Cramer Podcast, I actually never once was selecting or streaming the Jim Cramer podcast. if I recall correctly. "Jim Cramer" podcast was where the system Status had frozen 10 minutes before I ran my second test with SuperDebug off. I was actually selecting, pausing and playing selections from the "Freakonomics Podcast" and the "Forum Podcast". The PI updated status about midway through the test, on one of the calls to play a "Freakonomics Podcast - the latest one on the GooglePlay playlist. I ended with the Fitness podcast, which the PI handled correctly.

If my recollection is correct, perhaps sonos didn't alert you to the fact that I was changing playlists and episodes.

Anyways, I'm about to install everything on another computer, so that will allow me to see if I can duplicate my symptoms on a fresh install This is a symptom of the PI never updating its status on certain playlists, so I'm hoping it goes away under the new install, and we can chalk it up to Gremlins.

**dcorsus** · January 4, 2019, 09:03 PM

Suggest simple filter and look at life log entries .....
I noticed Freakonomics in the other file you had posted before

Announcement

Sonos plugin Freezes Device Update along certain paths

Sonos plugin Freezes Device Update along certain paths

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment