Announcement

Collapse
No announcement yet.

HS3 Linux and Windows SONOS PI version

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

    #76
    Originally posted by teladog01 View Post
    Dirk,

    Here's the Sonos errors in the log from today:

    Code:
    Feb-05 5:26:10 PM         Sonos Error    ERROR in SetPlayMode for zoneplayer = Basement with UPNP Error = Read only tag / Transport is locked / Access denied. Error = MyUPnPService.InvokeAction for ServiceID = http://10.3.11.124:1400/xml/AVTransport1.xml while sending Action = SetPlayMode for URI = http://10.3.11.124:1400/MediaRenderer/AVTransport/Control and Request = 0 REPEAT_ALL UPNP Error = faultcode = s:Client, faultstring = UPnPError, detail = 712 with error = The remote server returned an error: (500) Internal Server Error.
    Feb-05 5:26:10 PM         Sonos Error    ERROR in SetPlayMode for zoneplayer = Living Room with UPNP Error = Read only tag / Transport is locked / Access denied. Error = MyUPnPService.InvokeAction for ServiceID = http://10.3.11.109:1400/xml/AVTransport1.xml while sending Action = SetPlayMode for URI = http://10.3.11.109:1400/MediaRenderer/AVTransport/Control and Request = 0 REPEAT_ALL UPNP Error = faultcode = s:Client, faultstring = UPnPError, detail = 712 with error = The remote server returned an error: (500) Internal Server Error.
    Feb-05 5:26:11 PM         Sonos Error    ERROR in SetPlayMode for zoneplayer = Kitchen with UPNP Error = Read only tag / Transport is locked / Access denied. Error = MyUPnPService.InvokeAction for ServiceID = http://10.3.11.196:1400/xml/AVTransport1.xml while sending Action = SetPlayMode for URI = http://10.3.11.196:1400/MediaRenderer/AVTransport/Control and Request = 0 REPEAT_ALL UPNP Error = faultcode = s:Client, faultstring = UPnPError, detail = 712 with error = The remote server returned an error: (500) Internal Server Error.
    Feb-05 5:26:11 PM         Sonos Error    ERROR in SetPlayMode for zoneplayer = Bathroom with UPNP Error = Read only tag / Transport is locked / Access denied. Error = MyUPnPService.InvokeAction for ServiceID = http://10.3.11.135:1400/xml/AVTransport1.xml while sending Action = SetPlayMode for URI = http://10.3.11.135:1400/MediaRenderer/AVTransport/Control and Request = 0 REPEAT_ALL UPNP Error = faultcode = s:Client, faultstring = UPnPError, detail = 712 with error = The remote server returned an error: (500) Internal Server Error.
    Feb-05 5:37:04 PM         Sonos Error    ERROR in PlayURI for zoneplayer = Front Bedroom with UPNP Error = Read only tag / Transport is locked / Access denied. URI=x-rincon:RINCON_000E58B6AE2501400 and isObjectID = False, MetaData=, Error =MyUPnPService.InvokeAction for ServiceID = http://10.3.11.140:1400/xml/AVTransport1.xml while sending Action = SetAVTransportURI for URI = http://10.3.11.140:1400/MediaRenderer/AVTransport/Control and Request = 0 x-rincon:RINCON_000E58B6AE2501400 UPNP Error = faultcode = s:Client, faultstring = UPnPError, detail = 501 with error = The remote server returned an error: (500) Internal Server Error.
    Feb-05 5:37:06 PM         Sonos Error    ERROR in PlayURI for zoneplayer = Bathroom with UPNP Error = Read only tag / Transport is locked / Access denied. URI=x-rincon:RINCON_000E58B6AE2501400 and isObjectID = False, MetaData=, Error =MyUPnPService.InvokeAction for ServiceID = http://10.3.11.135:1400/xml/AVTransport1.xml while sending Action = SetAVTransportURI for URI = http://10.3.11.135:1400/MediaRenderer/AVTransport/Control and Request = 0 x-rincon:RINCON_000E58B6AE2501400 UPNP Error = faultcode = s:Client, faultstring = UPnPError, detail = 501 with error = The remote server returned an error: (500) Internal Server Error.
    Attached is the Sonos debug log from when I restarted the plugin last night until now.

    Thanks for your help.
    Hi Teladog01,

    I looked at the traces.

    There are 2 issues:

    1/ you have errors on SetPlayMode, I'm going to simply suppress these because they are benign and are caused by some idiosyncrasies that Sonos has.

    2/ There is an error on playing the radiostation. This I suspect is the players choking a little on all the actions been fired at them. When you play a radiostation, depending on your internet BW or other factors, it could take many seconds before the stream is actually buffered and playing. Not sure that the event in the log is the same action details as you posted above, you may have a logic conflict in your event (it fired at 5:37pm). I can see the Front Bedroom player being instructed to play a radiostation but than instructed I believe to link with itself while it is still trying to start playing the radiostation. Check the event for mistakes! The sequence I would follow for these events, assuming the event only fires when the player is not playing, it is safe to FIRST link the players, that will cause all players in the link group to stop playing. Then set the volume and last what to play (radiostation, track ...) so the delay that might happen to start playing won't affect any other action in your event. If you program a "LINK" Sonos Command, make sure you don't have the Master player as part of your "to be linked" players.

    Dirk

    Comment


      #77
      Originally posted by dcorsus View Post
      Hi Teladog01,

      I looked at the traces.

      There are 2 issues:

      1/ you have errors on SetPlayMode, I'm going to simply suppress these because they are benign and are caused by some idiosyncrasies that Sonos has.

      2/ There is an error on playing the radiostation. This I suspect is the players choking a little on all the actions been fired at them. When you play a radiostation, depending on your internet BW or other factors, it could take many seconds before the stream is actually buffered and playing. Not sure that the event in the log is the same action details as you posted above, you may have a logic conflict in your event (it fired at 5:37pm). I can see the Front Bedroom player being instructed to play a radiostation but than instructed I believe to link with itself while it is still trying to start playing the radiostation. Check the event for mistakes! The sequence I would follow for these events, assuming the event only fires when the player is not playing, it is safe to FIRST link the players, that will cause all players in the link group to stop playing. Then set the volume and last what to play (radiostation, track ...) so the delay that might happen to start playing won't affect any other action in your event. If you program a "LINK" Sonos Command, make sure you don't have the Master player as part of your "to be linked" players.

      Dirk
      1/ The SetPlayMode errors at 5:26:10 PM were from a Sonos TTS event, and there was nothing playing on any of the players at the time. I haven't noticed any issues with TTS events as far as players not playing. So as you mentioned these may be benign.

      2/ The errors at 5:37 were indeed from the event in the screenshot I posted. When I see errors from this event, they do correspond with players not playing. I double checked and the event is not linking Front Bedroom to itself. Do you see anything else wrong with the event I posted? From your advice above, should I swap the Link and Play actions, i.e. Link, then Volume, then Play?

      Comment


        #78
        Originally posted by teladog01 View Post
        From your advice above, should I swap the Link and Play actions, i.e. Link, then Volume, then Play?
        YES

        Comment


          #79
          Originally posted by dcorsus View Post
          Hi Teladog01,

          I can see the Front Bedroom player being instructed to play a radiostation but than instructed I believe to link with itself while it is still trying to start playing the radiostation.

          Dirk
          After looking at this some more, I think the Front Bedroom was probably already linked to the Living Room when the Play action for the Living Room executes. Does that explain why the trace showed the Front Bedroom being linked to itself? I suppose changing the order of actions to link before playing will avoid this.

          Comment


            #80
            new version 13 to be available in the updater

            Changes to v3.1.0.13
            • Support multiple speaker clients in a single event
            • Voice tags will be lifted from announcement text to change preferred voice
            • Fixed issue with play-state-change trigger event missing when zones are linked
            • Fixed issue where the track position counter keeps counting up after initially linking players
            • Fixed some issue with name change of players when paired
            • Fixed some issues w/ Playbars paired to S1 players
            • Heavy logging of the PI under Linux causes resource leaks, fixed.
            • Fixed issue with international character set (in this case Norwegian) in zone names.

            Comment


              #81
              Issue freezing events after a day running Sonso

              Dirk,

              I have an issue with the 3.1.0.0.12 plugin. I have tested this for a few weeks as I wanted to be sure what was happening.
              I noticed that after settling my experiments with your plugin and subsequent changes you made for me in the plugin that HS3 was no longer executing events after it had been running for more or less a day. The processor usage (HS3.exe) would jump up to 30% once this situation arises and stay there, where normal CPU usage on this machine is around 8% for all processes. A restart of HS3 solves the issue for a day and then freezing of events comes back again. It feels like there is a build up in slowness as just before this situation starts it seems that lagging occurs in HS3 events.

              This slowness is only hitting the triggering of events as other updates, like updates from physical devices (with their plugins) are still coming in th HS3 system and are still updated fast. But once the device is updated, an event that should be triggered by that value change does no longer trigger. Not one. I used the SimpleEventViewer from jon00 to have a good overview on the events triggered over time. If I let this situation stay for an hour, then during this hour no events will trigger, unless I do the restart of HS3.

              It took me a while of experimenting with all plugins, but I noticed the system would run like normal for multiple days again when I disable the Sonos plugin during this period. Re-enabling the Sonos plugin would bring the events to stop again within 24 hours.
              In the next step I checked what the plugin does on events. I had created several events using sonos triggers(Sonos Stop) and conditions (Loudness,IsNotPlaying, IsPlaying). So I disabled them and left the plugin running. At this point the events in HS3 became slow (more or less 2 or 3 seconds of delays) after a day, but HS3 events keep getting triggered normal, even with two days of running. If I disable the plugin at this point without restarting HS3, the system becomes snappy again after more or less half an hour. The last test I have never done with the Sonos events enabled as we were then mostly in the dark when it started and we needed response from HS3 soon.

              My impression is that the freezing of events started most time when the Sonos system was active with music or TV. But I did not check that enough to be sure about this.

              I am hoping you might have seen the same also and maybe have ideas how to solve this issue?

              Wim
              -- Wim

              Plugins: JowiHue, RFXCOM, Sonos4, Jon00's Perfmon and Network monitor, EasyTrigger, Pushover 3P, rnbWeather, BLBackup, AK SmartDevice, Pushover, PHLocation, Zwave, GCalseer, SDJ-Health, Device History, BLGData

              1210 devices/features ---- 392 events ----- 40 scripts

              Comment


                #82
                Originally posted by w.vuyk View Post
                Dirk,

                I have an issue with the 3.1.0.0.12 plugin. I have tested this for a few weeks as I wanted to be sure what was happening.
                I noticed that after settling my experiments with your plugin and subsequent changes you made for me in the plugin that HS3 was no longer executing events after it had been running for more or less a day. The processor usage (HS3.exe) would jump up to 30% once this situation arises and stay there, where normal CPU usage on this machine is around 8% for all processes. A restart of HS3 solves the issue for a day and then freezing of events comes back again. It feels like there is a build up in slowness as just before this situation starts it seems that lagging occurs in HS3 events.

                This slowness is only hitting the triggering of events as other updates, like updates from physical devices (with their plugins) are still coming in th HS3 system and are still updated fast. But once the device is updated, an event that should be triggered by that value change does no longer trigger. Not one. I used the SimpleEventViewer from jon00 to have a good overview on the events triggered over time. If I let this situation stay for an hour, then during this hour no events will trigger, unless I do the restart of HS3.

                It took me a while of experimenting with all plugins, but I noticed the system would run like normal for multiple days again when I disable the Sonos plugin during this period. Re-enabling the Sonos plugin would bring the events to stop again within 24 hours.
                In the next step I checked what the plugin does on events. I had created several events using sonos triggers(Sonos Stop) and conditions (Loudness,IsNotPlaying, IsPlaying). So I disabled them and left the plugin running. At this point the events in HS3 became slow (more or less 2 or 3 seconds of delays) after a day, but HS3 events keep getting triggered normal, even with two days of running. If I disable the plugin at this point without restarting HS3, the system becomes snappy again after more or less half an hour. The last test I have never done with the Sonos events enabled as we were then mostly in the dark when it started and we needed response from HS3 soon.

                My impression is that the freezing of events started most time when the Sonos system was active with music or TV. But I did not check that enough to be sure about this.

                I am hoping you might have seen the same also and maybe have ideas how to solve this issue?

                Wim
                What kind of PC are you running this on? Windows or Linux? VM or native? Have you checked free-memory when it happens? Do you have the logging of the PI, especially disk-logging off?

                Dirk

                Comment


                  #83
                  Dirk,

                  It is on a Windows physical machine - sorry, thougt I was posting in the beta thread, did not realise this was the linux thread...),. No logging enabled. When the system is running there is 750Mb still free memory, I did not notice this changing during event freezing...

                  Wim
                  -- Wim

                  Plugins: JowiHue, RFXCOM, Sonos4, Jon00's Perfmon and Network monitor, EasyTrigger, Pushover 3P, rnbWeather, BLBackup, AK SmartDevice, Pushover, PHLocation, Zwave, GCalseer, SDJ-Health, Device History, BLGData

                  1210 devices/features ---- 392 events ----- 40 scripts

                  Comment


                    #84
                    Originally posted by w.vuyk View Post
                    Dirk,

                    It is on a Windows physical machine - sorry, thougt I was posting in the beta thread, did not realise this was the linux thread...),. No logging enabled. When the system is running there is 750Mb still free memory, I did not notice this changing during event freezing...

                    Wim

                    This is the right thread for this version of the PI. How many events do you have that trigger an announcement? Do all of them now have the SAPI tags in them to change the voice? If so, could any of them have a typo that could cause perhaps a SW loop in my PI (I need to check the code again tonight to see if there is a possibility for a SW loop). So check all events that use announcements and see if they are all the same and have no typos in them. Perhaps post the syntax of them here. Are you using scripts? If so, you sure the issue is not in the script itself?

                    Dirk

                    Comment


                      #85
                      Dirk,

                      it is not the announcement I think. Although the announcement script I created was running during the test without Sonos trigger/condition events. This script is now called instead of using the speak action of hs3. But the frequency of running is not really often, where the Sonos trigger could be called every second, and conditions every few seconds? I am attaching all images of my events, it is not even that high a number of events.
                      To be complete, here is also the speak script (there is only one called by differtent events), one sample event calling speak.vb is also attached as image. Only one event "weersvoorspelling" is using the voice tags through weatherxml, but runs only once per hour at the most.

                      Code:
                      Sub Main(ByVal parmarray As Object)
                          Dim VoiceFemale As String = "<voice required='Name=IVONA 2 Lotte - Dutch female voice [22kHz]'>"
                          Dim VoiceMale As String = "<voice required='Name=IVONA 2 Ruben - Dutch male voice [22kHz]'>"
                          'Dim VoiceFemale As String = "<voice required='Name=IVONA 2 Lotte'>"
                         ' Dim VoiceMale As String = "<voice required='Name=IVONA 2 Ruben'>"
                          Dim Sonos As String = "$SONOS$ALL$:*"
                          Dim EndVoice As String = "</voice>"
                          Dim Params() As String = parmarray.split(",")
                          If Params.count < 1 Or Params.count > 2 Then
                              hs.writelog("SpeakerHelper", "Not the right number of parameters for this script, exiting")
                              Exit Sub
                          End If
                          hs.speak(Params(0))
                          ' hs.writelog("SpeakerHelper", Params(0))
                      
                          hs.speak("C:\HS3\Wave\voy_door_chime.mp3|" & VoiceMale & Params(0) & EndVoice & "|C:\HS3\Wave\voy_door_chime.mp3", False, Sonos)
                      
                      End Sub
                      Wim
                      Attached Files
                      -- Wim

                      Plugins: JowiHue, RFXCOM, Sonos4, Jon00's Perfmon and Network monitor, EasyTrigger, Pushover 3P, rnbWeather, BLBackup, AK SmartDevice, Pushover, PHLocation, Zwave, GCalseer, SDJ-Health, Device History, BLGData

                      1210 devices/features ---- 392 events ----- 40 scripts

                      Comment


                        #86
                        Originally posted by w.vuyk View Post
                        Dirk,

                        it is not the announcement I think. Although the announcement script I created was running during the test without Sonos trigger/condition events. This script is now called instead of using the speak action of hs3. But the frequency of running is not really often, where the Sonos trigger could be called every second, and conditions every few seconds? I am attaching all images of my events, it is not even that high a number of events.
                        To be complete, here is also the speak script (there is only one called by differtent events), one sample event calling speak.vb is also attached as image. Only one event "weersvoorspelling" is using the voice tags through weatherxml, but runs only once per hour at the most.

                        Code:
                        Sub Main(ByVal parmarray As Object)
                            Dim VoiceFemale As String = "<voice required='Name=IVONA 2 Lotte - Dutch female voice [22kHz]'>"
                            Dim VoiceMale As String = "<voice required='Name=IVONA 2 Ruben - Dutch male voice [22kHz]'>"
                            'Dim VoiceFemale As String = "<voice required='Name=IVONA 2 Lotte'>"
                           ' Dim VoiceMale As String = "<voice required='Name=IVONA 2 Ruben'>"
                            Dim Sonos As String = "$SONOS$ALL$:*"
                            Dim EndVoice As String = "</voice>"
                            Dim Params() As String = parmarray.split(",")
                            If Params.count < 1 Or Params.count > 2 Then
                                hs.writelog("SpeakerHelper", "Not the right number of parameters for this script, exiting")
                                Exit Sub
                            End If
                            hs.speak(Params(0))
                            ' hs.writelog("SpeakerHelper", Params(0))
                        
                            hs.speak("C:\HS3\Wave\voy_door_chime.mp3|" & VoiceMale & Params(0) & EndVoice & "|C:\HS3\Wave\voy_door_chime.mp3", False, Sonos)
                        
                        End Sub
                        Wim

                        Don't spot anything off. When these delays are happening, if you turn on the Sonos debug flag, is the PI doing anything? If so, is it doing a lot or just few things but very slow?

                        Did you mention, you call the PI every second with a trigger?

                        Thanks

                        Dirk
                        postedit: did you mean trigger or condition every second or few seconds? If so, which condition are we talking about here?

                        Comment


                          #87
                          Dirk,

                          I was mentioning that having a trigger in a plugin will cause HS3 callback the plugin every second, it does the same with my own JowiHue plugin also. So I am not calling the plugin, Hs does callback to triggertrue very often.
                          It depends ofcourse on the plugins handling, but if the plugin needs a lot of handling to decide if it should return true for a trigger or condition, it might slowdown HS3 events?
                          The callback to conditions might be slower, depending on the preceding trigger and conditions.

                          I will test with the enabled plugin and activate trace. But that might take a few days, depending on the WAF

                          Wim
                          -- Wim

                          Plugins: JowiHue, RFXCOM, Sonos4, Jon00's Perfmon and Network monitor, EasyTrigger, Pushover 3P, rnbWeather, BLBackup, AK SmartDevice, Pushover, PHLocation, Zwave, GCalseer, SDJ-Health, Device History, BLGData

                          1210 devices/features ---- 392 events ----- 40 scripts

                          Comment


                            #88
                            Originally posted by w.vuyk View Post
                            Dirk,

                            I was mentioning that having a trigger in a plugin will cause HS3 callback the plugin every second, it does the same with my own JowiHue plugin also. So I am not calling the plugin, Hs does callback to triggertrue very often.
                            It depends ofcourse on the plugins handling, but if the plugin needs a lot of handling to decide if it should return true for a trigger or condition, it might slowdown HS3 events?
                            The callback to conditions might be slower, depending on the preceding trigger and conditions.

                            I will test with the enabled plugin and activate trace. But that might take a few days, depending on the WAF

                            Wim
                            HS doesn't call TriggerTrue every second unless you have an event with a condition that is being checked every second. If you set the PIs debug flag, you would see a log entry every second.

                            Triggers are calls from the PI TO HS, HS calls for conditions, but the procedure is indeed called TriggerTrue, confusing.

                            Just looked at my code, if you were to check on a player Mute state as a condition, this apparently was going out to the player each time, so if there is an issue with reaching the player, you would see delays. Will be fixed in next version, not sure why I did that in the past.

                            Also re-read the code I added for the voice-tags. Nothing in there that could case a loop and cause major delays.

                            Dirk
                            postedit: how is your settings to create a musicDB? Trust it is not set to immediate because when the MusicDB is created, the PI is very busy so CPU will be high and response will be slow but a debug log should easily show you that.

                            Comment


                              #89
                              Dirk,

                              I have no conditions on mute here.

                              I have re-enabled the plugin and enabled all events again. Once I see the events freezing I will enable logging in the plugin. Do you have a preferred level, so I am sure to see things happen in the log when the plugin is busy with something?

                              I have enabled the debug flag here with the events enabled as well shortly and did not see an every second entry in the log, so I guess the conditions are not pulling on the plugin yet. A radiostation is playing..

                              Wim
                              -- Wim

                              Plugins: JowiHue, RFXCOM, Sonos4, Jon00's Perfmon and Network monitor, EasyTrigger, Pushover 3P, rnbWeather, BLBackup, AK SmartDevice, Pushover, PHLocation, Zwave, GCalseer, SDJ-Health, Device History, BLGData

                              1210 devices/features ---- 392 events ----- 40 scripts

                              Comment


                                #90
                                Originally posted by w.vuyk View Post
                                Do you have a preferred level, so I am sure to see things happen in the log when the plugin is busy with something?
                                Nope, just (only) the PI debug flag, leave UPNP level at errors only.
                                Maybe the issue is with the installed voices/speaker client that is delaying things? When it happens, check for memory and handle utilization.

                                Dirk

                                Comment

                                Working...
                                X