Remotely reboot a SONOS device

[paul]

Doesn't look like it, however I did reboot hs3 a couple of days ago, and I believe the issue reoccurred prior to that last reboot (and HS3 reboots don't seem to get the speaker back, just speaker reboots). But I'll definitely be aware of it moving forward, after getting it working again tonight, if the problem reoccurs I'll get a dump of the HS3 log prior to doing anything else....

[dcorsus]

Doesn't look like it, however I did reboot hs3 a couple of days ago, and I believe the issue reoccurred prior to that last reboot (and HS3 reboots don't seem to get the speaker back, just speaker reboots). But I'll definitely be aware of it moving forward, after getting it working again tonight, if the problem reoccurs I'll get a dump of the HS3 log prior to doing anything else....

If you rebooted HS a few days ago and the issue is there right now, I would be very interested in the whole HS log. It should be under <HS root>\logs and is in an SQLite format but that’s ok. Could you zip that and pm me

[dcorsus]

If you rebooted HS a few days ago and the issue is there right now, I would be very interested in the whole HS log. It should be under <HS root>\logs and is in an SQLite format but that’s ok. Could you zip that and pm me

Moreover , after you send me that log, I would actually prefer to see a restart of HS with all the logging active and figure out why a HS restart didn’t solve it, it must show a problem with discovery

[paul]

Sure thing, I can do that. Will send it as soon as I can....

[dcorsus]

Sure thing, I can do that. Will send it as soon as I can....

Thanks so do the HS restart before trying to booting or disconnecting the Zander player. I’m now ver curious to see what you experience with:

HS restart
player disconnect for 1 hour
player reboot

[paul]

Ok, so it looks like my homeseer log actually goes back to sometime in October. Here's the whole thing:

http://www.fielding.ca/sonosdebug/HomeSeerLog.hsd.zip

Unfortunately I don't have timestamps for you in that log, but if you're able to discern anything weird with the Zander speaker, that'd be awesome. Gonna setup logging and testing right now as previously discussed.

Paul

[dcorsus]

Ok, so it looks like my homeseer log actually goes back to sometime in October. Here's the whole thing:

http://www.fielding.ca/sonosdebug/HomeSeerLog.hsd.zip

Unfortunately I don't have timestamps for you in that log, but if you're able to discern anything weird with the Zander speaker, that'd be awesome. Gonna setup logging and testing right now as previously discussed.

Paul

No revelations but noted that your system is being reset at 3:30 am on some days but nothing off there. Then I see all players drop off on the 31st at 9:05pm. Interesting enough you HStouch clients seems to be coming and going around the same time frame, but looking at it some more, your clients seems to be coming and going all the time, what's up with that?
Other than that ,nothing off......

[paul]

Ok here's the first part - debug logs for the following:

- 22:40:30 - changed track to Sleepy Starry Sky
- 22;41:02 - paused
- 22:41:23 - played
- 22:42:24 - ran event "Play Hot Air Balloons Zanders Room" (Nothing happened)
- 22:45:40 - pressed pause on Homeseer for zanders room (nothing happened)
- 22;45:55 - pressed play on Homeseer for zander's room (nothing happened)
- waited an hour, then turned off logging

(I noticed after that my laptop may be a second out from my HS server, so these stamps might be out by a second.)

As it turns out, kid had to go to bed, so I can't get in there to do the unplugging right now. Sorry. Fortunately for our purposes the speaker will most likely remain unavailable overnight. So tomorrow I'll make sure turn logging back on and test, do the restart HS and test, unplug speaker, plug back in and test (as per previous messages) and get you the results.....

Here's the debug log:

http://www.fielding.ca/sonosdebug/SonosDebug.txt.zip

regards,

Paul

[paul]

No revelations but noted that your system is being reset at 3:30 am on some days but nothing off there. Then I see all players drop off on the 31st at 9:05pm. Interesting enough you HStouch clients seems to be coming and going around the same time frame, but looking at it some more, your clients seems to be coming and going all the time, what's up with that?
Other than that ,nothing off......

Heh. Yeah the 3:30am reset is something I have running a few times per week as a holdover from a few years ago when I was having issues with my HS server running out of resources and hanging. I've changed machines since then so I suspect I could probably remove that now altogether without issue, That being said, yesterday I disabled it so that it doesn't keep resetting while I'm troubleshooting this issue.

I don't know for sure what happened at 9:05pm on the 31st when they dropped off, I didn't do it, at least not that I can recall. Wierd. HS Touch clients coming and going is normal - we use HSTouch on our phones, and I have a wall mounted ipad that is normally on HSTouch, but my daughter sometimes flips it to Sonos to rig up her own playlists, then switches it back.

I'll be interested to see what we can get from the restarts tomorrow.....

Paul

[dcorsus]

I'll be interested to see what we can get from the restarts tomorrow.....

The logs have been VERY helpful. I now have a picture of what might be wrong, just absolutely no idea how I got into this state or why I cannot find ANY error in your logs. Moreover, a restart of HS3, if that doesn't take care of the issue, there MUST be an error unless you had all setting to off (I recommend people leave UPNP level to error only!). By the way, I see almost ALL your players to be in a stuck state, there is only a few who are properly responding and sending out renews.

So whatever further actions you take, be it taking the player off line for short or long times or do a restart of HS (note HS not PI as I want to make sure the PI was restarted cleanly), make sure the PI debug is ON, no superdebug (too much irrelevant stuff for this problem) and at least UPNP debug level is events.

My working theory is that, perhaps a race condition happened, where a player goes off-line and immediately is rediscovered, somehow leaving the PI to believe the player is on-line but all services have not been subscribed to, as I said, I have no idea how this would happen, but that's how it right now looks. In this case, unless the Sonos player sends a ssdp:byebye at reboot, the PI wouldn't notice anything is wrong unless you leave the player off-line for 1 hour.

So eager to read what you learned from your experiments.

Dirk

[paul]

Cool, I'm glad the logs have been helpful. Didn't get to doing the restarts yesterday, but am working from home today so am hoping to test shortly and will send you the logs....

Paul

[dcorsus]

Cool, I'm glad the logs have been helpful. Didn't get to doing the restarts yesterday, but am working from home today so am hoping to test shortly and will send you the logs....

Paul

Hi Paul, I assume you got sidetracked or did I miss the logs?

[paul]

Hey, sorry yeah got sidetracked by a family emergency (all is well). Gonna try again for tomorrow.... 🤣

[paul]

edit: initially gave bad URL. Is fixed.

Hey Dirk,

OK!!! Sorry, was a wild week. I finally was able to sit down today and get the logs. Here's the link to the logfile:

http://www.fielding.ca/sonosdebug/SonosDebug4.zip

It includes both the Sonos Debug log, and the HS3 log.

Here's what I did while debug was on:

Nov 15, 2020
3:11:xx pm - enabled debug logging and checked that all players show online in HS.
3:13:00 pm - ran event that changes the playlist in Zander's room, sets repeat and volume, and plays
- Nothing happened on the actual Sonos device, Sonos App shows nothing changed.
3:15:35 pm - From Sonos App, changed playlist to "Mystical Healing Garden".
- See nothing change in HS3 UI.
3:18:xx pm - Stopped HS3 - made sure all plugin processes stopped fully
3:19:00 pm - Started HS3
4:20:40 pm - Tried running event on zander's room again to see if it worked after reboot. Got nothing.
4:22:29 pm - unplugged zander's speaker.
4:23:30 pm - plugged it back in.
- I noticed after this that HS3 updated to show Zander's room stopped.
4:27:00 pm - ran event from HS - This time Speaker updated, and started playing appropriately
4:28:00 pm - changed song on Speaker to Ocean Waves, which was picked up by HS3 and trigged my white noise event appropriately.
5:47:xx pm - turned off debug logging


I made a point of leaving things for an hour after restarting HS3, and leaving things for an hour after rebooting the speaker and testing it, just in case you get anything useful from the log.

If I can try anything else don't hesitate to let me know!

thanks,

Paul

[dcorsus]

I made a point of leaving things for an hour after restarting HS3, and leaving things for an hour after rebooting the speaker and testing it, just in case you get anything useful from the log.

If I can try anything else don't hesitate to let me know!

thanks,

Paul

This log confirms further that something really bizarre is going on. Just some background:

1/ at start-up the PI calls my UPNP subsystem, which subsequently does discovery of all players. The log shows that this subsystem finds 9 Sonos devices (including your bridge).
2/ All info is returned to the PI and the PI now starts to compare devices alive versus devices that are in the HS database

This is were things are bizarre, the PI, out of the 9 devices, only retrieves 5 ???? Unfortunately there isn't any debug logs around that code that would provide us better insight. Moreover, I have a 5 minute audit running that should catch this but that wasn't doing it either.

I think you wrote somewhere you are in Win7, is that correct? If so, is this Win7 up to date on .NET patches? The PI nowadays need v4.7.2

Here is what we can do:
- do a couple a restarts of HS3 with the PI debug flag on, UPNP debug log set to "errors only", else we have too many log entries
- each time the system is done initializing we filter for key word "FindZonePlayers" in the log (don't use the quotes!!)
- it should show we found 9 devices and used 8 of those.

If you don't get 9 devices discovered, the filtered log will show which players were found, which I believe means that those that are missing in the list, will actually not work. If it shows less than all the players, you could turn superdebug on and wait for ~ 6 minutes and now you should filter on "DoRediscover".

Would be curious what you learn.

As an alternative, we could also just decide to upgrade, the latest version is now .47 and is in the BETA section of the updater. It included quite a bit of optimization and robustness improvements in the area of handing UPNP devices. Having that said, the symptoms we see here, are totally different, so upgrading might not make any difference so if you go this route, you should continue to pay attention to logs with "FindZonePlayers" and check whether ALL players were properly found and processed. This new version you'll notice has changes to debug settings, there is no more PI superdebug flag, you use debug-level=Verbose to get the same. You should operate this version with both PI and UPNP debug log set to errors-only in regular operation.

In my mind, issues could be:
- .NET issue
- the UPNP subsystem while discovering devices, comes across a non-conforming UPNP device (I see some of them in your log) and somehow screws something up in the list it is creating that it is supposed to hand-off to the PI. Having that said, you posted the result when you click on "View Sonos Devices", and all of that looks OK.
- it is a timing/race condition thing because so many things are happening in parallel, it is very hard to follow the flow of ONE device going through all proper discovery steps.

There you have it. Did I mention that when you reboot the missing player, the device gets properly discovered and subsequently reported to the PI and all is working as it should. I suspect the HS3 restarts at night is what gets us in this bad state .... just can't find why. Quite ironic isn't it, suspect you added the nightly restarts to "clear" issues and they might turn out to be the trigger to this issue ... somehow.

Thanks for the effort, this is a tricky one.

Dirk