Announcement

Collapse
No announcement yet.

Remotely reboot a SONOS device

Collapse
X
 
  • Filter
  • Time
  • Show
Clear All
new posts

  • paul
    replied
    Just an update - since we did all this in November, it's been rock solid. Many thanks again!

    Leave a comment:


  • dcorsus
    replied
    Originally posted by paul View Post
    Ok! Installed .49. Prior to doing so I tested another speaker that I had co firmed yesterday had stopped working. Still not working prior to update. Updated plugin, and without doing anything else that speaker started working correctly. Hopefully this will solve it! Thank you again for taking all the time you did to track this down!

    regards,

    Paul
    PFFFF, for a second I was afraid to read that after the upgrade it still didn't work

    You may spot a few changes here and there, the debug settings is now a level and in the player table you should see the on-line state in green or red.
    I decided to release this version as the new official version so hopefully we kick it hard enough to make it more robust.

    Enjoy your automation!

    Leave a comment:


  • paul
    replied
    Ok! Installed .49. Prior to doing so I tested another speaker that I had co firmed yesterday had stopped working. Still not working prior to update. Updated plugin, and without doing anything else that speaker started working correctly. Hopefully this will solve it! Thank you again for taking all the time you did to track this down!

    regards,

    Paul

    Leave a comment:


  • paul
    replied
    Sounds good. Thank you so much for digging through all my logs to get to the bottom of it. I’ll get the PI upgraded today and let you know the results!

    Leave a comment:


  • dcorsus
    replied
    paul No need to do further testing, I think I solved my own puzzle. The issue with not always discovering all the devices at startup has been there for many years. Somewhere in v27 I saw an issue with a periodic rediscovery function and I made a change. Unfortunately, the change prevented any rediscovery and I didn't notice it. I suspect at some point, I did notice that some players on my own system were missing and that's when I found the issue with the discovery at start-up, not realizing that the rediscovery change exposed this.
    Anyhow, there is a version .49 I posted in the beta section of the updater but I also submitted it to the HS team to be posted in the media section. So if you don't find it under the beta section, look for it in the media section.
    Let me know how things go but a big thanks for all the logs and sticking it out so we could undo all my mistakes.

    Leave a comment:


  • dcorsus
    replied
    Originally posted by paul View Post
    Hmmm.... I just checked the .net version. If I read it correctly (Release 528040) I'm at the newest release 4.8 right now. Assuming I have that right, I guess that's ruled out. I'm a believer in covering all the bases, so I'll try some restarts later tonight and see what we find. After that if there isn't anything that might indicate a resolution, I'd certainly be up for upgrading the PI if you think that's a good next step at that point...
    Paul, suggest you step up to the latest version. Finally realized what I see in your log, is something I fixed a while back (late Feb this year). I was looking at my latest code and couldn't quite figure out why the UPNP subsystem wasn't reporting all devices until it finally dawned on me what was wrong and when I looked at the old code, bam there it was; getting old sucks.

    Not quite sure why the periodic rediscovery didn't take care of things, going to look at that now, maybe I fixed that as well This rediscovery, to trace that, you do not need the UPNP logging to verbose but it requires superdebug to be turned on. It should kick in every 5 minutes and the key word is "DoRediscover"

    Dirk

    Leave a comment:


  • paul
    replied
    Hmmm.... I just checked the .net version. If I read it correctly (Release 528040) I'm at the newest release 4.8 right now. Assuming I have that right, I guess that's ruled out. I'm a believer in covering all the bases, so I'll try some restarts later tonight and see what we find. After that if there isn't anything that might indicate a resolution, I'd certainly be up for upgrading the PI if you think that's a good next step at that point...

    Leave a comment:


  • dcorsus
    replied
    Actually, just made another little improvement. When you ever move to version 48, the player table, in the column on-line will now show in green or red if there is an issue of state between the PI and UPNP subsystem, with RED being bad

    Leave a comment:


  • dcorsus
    replied
    Originally posted by paul View Post

    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







    Leave a comment:


  • paul
    replied
    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

    Leave a comment:


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

    Leave a comment:


  • dcorsus
    replied
    Originally posted by paul View Post
    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?

    Leave a comment:


  • paul
    replied
    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

    Leave a comment:


  • dcorsus
    replied
    Originally posted by paul View Post
    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





    Leave a comment:


  • paul
    replied
    Originally posted by dcorsus View Post

    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

    Leave a comment:

Working...
X