Announcement

Collapse
No announcement yet.

Frequent disconnects

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

    Frequent disconnects

    Hi Dirk, I am getting frequent disconnects between the plugin and my devices. It this related to IP adres renewal of the devices ? DHCP is set to always provide same adres via mac adres reservation. Any pointer as to what may be causing this ? Player table is showing ? in player connected column.

    Log entries below.

    Jan-18 9:42:58 PM Sonos Disconnect: Disconnected from ZonePlayer - Draagbaar

    Jan-18 9:42:58 PM Sonos Warning Reachable called for UPnPDevice Draagbaar which is not reachable anymore and set Off-line

    Jan-18 9:42:38 PM Sonos IPAddress for UPnPDevice = Draagbaar has changed. Old = 192.168.2.66. New =

    Jan-18 9:35:37 PM Sonos Disconnect: Disconnected from ZonePlayer - Living Room

    Jan-18 9:35:37 PM Sonos Warning Reachable called for UPnPDevice Living Room which is not reachable anymore and set Off-line

    Jan-18 9:35:17 PM Sonos IPAddress for UPnPDevice = Living Room has changed. Old = 192.168.2.65. New =

    Thanks,

    Evja

    #2
    Originally posted by evja78 View Post
    Hi Dirk, I am getting frequent disconnects between the plugin and my devices. It this related to IP adres renewal of the devices ? DHCP is set to always provide same adres via mac adres reservation. Any pointer as to what may be causing this ? Player table is showing ? in player connected column.

    Log entries below.

    Jan-18 9:42:58 PM Sonos Disconnect: Disconnected from ZonePlayer - Draagbaar

    Jan-18 9:42:58 PM Sonos Warning Reachable called for UPnPDevice Draagbaar which is not reachable anymore and set Off-line

    Jan-18 9:42:38 PM Sonos IPAddress for UPnPDevice = Draagbaar has changed. Old = 192.168.2.66. New =

    Jan-18 9:35:37 PM Sonos Disconnect: Disconnected from ZonePlayer - Living Room

    Jan-18 9:35:37 PM Sonos Warning Reachable called for UPnPDevice Living Room which is not reachable anymore and set Off-line

    Jan-18 9:35:17 PM Sonos IPAddress for UPnPDevice = Living Room has changed. Old = 192.168.2.65. New =

    Thanks,

    Evja
    Suspect network issues. Is this wireless?

    Comment


      #3
      Dirk, possible but unlikely. Continous ping shows no drops, LAN monitoring shows both players online for days. One device is wired (livingroom), the other is wireless (SonosNet). I enabled some of the debug logging, results below. Plugin version is 3.1.0.11

      This happens roughly every hour for both (not at same time). Could the UPNP dispose call be causing this ? Players are reachable just fine with the Sonos software when this occurs. Players do get rediscovered later. Log is bottom to top.


      Jan-19 9:22:09 PM Sonos DirectConnect for zoneplayer = Living Room added Image = /images/Sonos/Artwork/PlayerIcon_ZP90.png for HSRef = 4

      Jan-19 9:22:09 PM Sonos DirectConnect for zoneplayer = Living Room found Icon already stored at /images/Sonos/Artwork/PlayerIcon_ZP90.png

      Jan-19 9:22:09 PM Sonos DirectConnect for zoneplayer = Living Room found IconURL = http://192.168.2.65:1400/img/icon-ZP90.png

      Jan-19 9:22:09 PM Sonos DirectConnect called for Zone Living Room with device name = uuid:RINCON_000E58A0E51A01400 and Model = ZP90

      Jan-19 9:22:09 PM Sonos AddNewDiscoveredDevice for zoneplayer = Living Room found IconURL = http://192.168.2.65:1400/img/icon-ZP90.png

      Jan-19 9:22:09 PM Sonos AddNewDiscoveredDevice found Zone Name = Living Room with UDN = uuid:RINCON_000E58A0E51A01400 Friendly Name = 192.168.2.65 - Sonos CONNECT and Icon = living

      Jan-19 9:22:09 PM Sonos AddNewDiscoveredDevice dequeued UDN = RINCON_000E58A0E51A01400

      Jan-19 9:22:09 PM Sonos AddNewDiscoveredDevice is processing Notification queue with # elements = 1

      Jan-19 9:17:22 PM Sonos Disconnect: Disconnected from ZonePlayer - Living Room

      Jan-19 9:17:22 PM Sonos DeviceTrigger called for Zone - Living Room with Trigger = Sonos Player Offline

      Jan-19 9:17:22 PM Sonos PlayChangeNotifyCallback called for Zone - Living Room with ChangeType = DeviceStatusChanged and Changevalue = Offline and SendDeviceTrigger = True

      Jan-19 9:17:22 PM Sonos Warning Reachable called for UPnPDevice Living Room which is not reachable anymore and set Off-line

      Jan-19 9:17:22 PM Sonos CheckIPAddressChange for UPnPDevice = Living Room found IPPort =

      Jan-19 9:17:22 PM Sonos CheckIPAddressChange for UPnPDevice = Living Room found IPAddress =

      Jan-19 9:17:22 PM Sonos Reachable called for UPnPDevice Living Room which is not reachable but still on-line

      Jan-19 9:17:02 PM Sonos IPAddress for UPnPDevice = Living Room has changed. Old = 192.168.2.65. New =

      Jan-19 9:17:02 PM Sonos CheckIPAddressChange for UPnPDevice = Living Room found IPPort =

      Jan-19 9:17:02 PM Sonos CheckIPAddressChange for UPnPDevice = Living Room found IPAddress =

      Jan-19 9:17:01 PM Sonos Reachable called for UPnPDevice Living Room which is not reachable but still on-line

      Jan-19 9:16:46 PM Sonos MySSDP.RemoveDevices called with UDN = uuid:RINCON_000E58A0E51A01400

      Jan-19 9:16:46 PM Sonos MySSDP.RemoveDevices called with UDN = uuid:RINCON_000E58A0E51A01400

      Jan-19 9:16:46 PM Sonos MyUPnPDevices.Dispose called


      Jan-19 9:13:03 PM Sonos Disconnect: Disconnected from ZonePlayer - Draagbaar

      Jan-19 9:13:03 PM Sonos DeviceTrigger called for Zone - Draagbaar with Trigger = Sonos Player Offline

      Jan-19 9:13:03 PM Sonos PlayChangeNotifyCallback called for Zone - Draagbaar with ChangeType = DeviceStatusChanged and Changevalue = Offline and SendDeviceTrigger = True

      Jan-19 9:13:03 PM Sonos Warning Reachable called for UPnPDevice Draagbaar which is not reachable anymore and set Off-line

      Jan-19 9:13:03 PM Sonos CheckIPAddressChange for UPnPDevice = Draagbaar found IPPort =

      Jan-19 9:13:03 PM Sonos CheckIPAddressChange for UPnPDevice = Draagbaar found IPAddress =

      Jan-19 9:13:03 PM Sonos Reachable called for UPnPDevice Draagbaar which is not reachable but still on-line

      Jan-19 9:12:43 PM Sonos IPAddress for UPnPDevice = Draagbaar has changed. Old = 192.168.2.66. New =

      Jan-19 9:12:43 PM Sonos CheckIPAddressChange for UPnPDevice = Draagbaar found IPPort =

      Jan-19 9:12:43 PM Sonos CheckIPAddressChange for UPnPDevice = Draagbaar found IPAddress =

      Jan-19 9:12:43 PM Sonos Reachable called for UPnPDevice Draagbaar which is not reachable but still on-line

      Jan-19 9:12:32 PM Sonos MySSDP.RemoveDevices called with UDN = uuid:RINCON_000E58C6EE0801400

      Jan-19 9:12:32 PM Sonos MySSDP.RemoveDevices called with UDN = uuid:RINCON_000E58C6EE0801400

      Jan-19 9:12:32 PM Sonos MyUPnPDevices.Dispose called

      Thanks !

      Evja

      Comment


        #4
        Originally posted by evja78 View Post
        Dirk, possible but unlikely. Continous ping shows no drops, LAN monitoring shows both players online for days. One device is wired (livingroom), the other is wireless (SonosNet). I enabled some of the debug logging, results below. Plugin version is 3.1.0.11

        This happens roughly every hour for both (not at same time). Could the UPNP dispose call be causing this ? Players are reachable just fine with the Sonos software when this occurs. Players do get rediscovered later. Log is bottom to top.


        Jan-19 9:22:09 PM Sonos DirectConnect for zoneplayer = Living Room added Image = /images/Sonos/Artwork/PlayerIcon_ZP90.png for HSRef = 4

        Jan-19 9:22:09 PM Sonos DirectConnect for zoneplayer = Living Room found Icon already stored at /images/Sonos/Artwork/PlayerIcon_ZP90.png

        Jan-19 9:22:09 PM Sonos DirectConnect for zoneplayer = Living Room found IconURL = http://192.168.2.65:1400/img/icon-ZP90.png

        Jan-19 9:22:09 PM Sonos DirectConnect called for Zone Living Room with device name = uuid:RINCON_000E58A0E51A01400 and Model = ZP90

        Jan-19 9:22:09 PM Sonos AddNewDiscoveredDevice for zoneplayer = Living Room found IconURL = http://192.168.2.65:1400/img/icon-ZP90.png

        Jan-19 9:22:09 PM Sonos AddNewDiscoveredDevice found Zone Name = Living Room with UDN = uuid:RINCON_000E58A0E51A01400 Friendly Name = 192.168.2.65 - Sonos CONNECT and Icon = living

        Jan-19 9:22:09 PM Sonos AddNewDiscoveredDevice dequeued UDN = RINCON_000E58A0E51A01400

        Jan-19 9:22:09 PM Sonos AddNewDiscoveredDevice is processing Notification queue with # elements = 1

        Jan-19 9:17:22 PM Sonos Disconnect: Disconnected from ZonePlayer - Living Room

        Jan-19 9:17:22 PM Sonos DeviceTrigger called for Zone - Living Room with Trigger = Sonos Player Offline

        Jan-19 9:17:22 PM Sonos PlayChangeNotifyCallback called for Zone - Living Room with ChangeType = DeviceStatusChanged and Changevalue = Offline and SendDeviceTrigger = True

        Jan-19 9:17:22 PM Sonos Warning Reachable called for UPnPDevice Living Room which is not reachable anymore and set Off-line

        Jan-19 9:17:22 PM Sonos CheckIPAddressChange for UPnPDevice = Living Room found IPPort =

        Jan-19 9:17:22 PM Sonos CheckIPAddressChange for UPnPDevice = Living Room found IPAddress =

        Jan-19 9:17:22 PM Sonos Reachable called for UPnPDevice Living Room which is not reachable but still on-line

        Jan-19 9:17:02 PM Sonos IPAddress for UPnPDevice = Living Room has changed. Old = 192.168.2.65. New =

        Jan-19 9:17:02 PM Sonos CheckIPAddressChange for UPnPDevice = Living Room found IPPort =

        Jan-19 9:17:02 PM Sonos CheckIPAddressChange for UPnPDevice = Living Room found IPAddress =

        Jan-19 9:17:01 PM Sonos Reachable called for UPnPDevice Living Room which is not reachable but still on-line

        Jan-19 9:16:46 PM Sonos MySSDP.RemoveDevices called with UDN = uuid:RINCON_000E58A0E51A01400

        Jan-19 9:16:46 PM Sonos MySSDP.RemoveDevices called with UDN = uuid:RINCON_000E58A0E51A01400

        Jan-19 9:16:46 PM Sonos MyUPnPDevices.Dispose called


        Jan-19 9:13:03 PM Sonos Disconnect: Disconnected from ZonePlayer - Draagbaar

        Jan-19 9:13:03 PM Sonos DeviceTrigger called for Zone - Draagbaar with Trigger = Sonos Player Offline

        Jan-19 9:13:03 PM Sonos PlayChangeNotifyCallback called for Zone - Draagbaar with ChangeType = DeviceStatusChanged and Changevalue = Offline and SendDeviceTrigger = True

        Jan-19 9:13:03 PM Sonos Warning Reachable called for UPnPDevice Draagbaar which is not reachable anymore and set Off-line

        Jan-19 9:13:03 PM Sonos CheckIPAddressChange for UPnPDevice = Draagbaar found IPPort =

        Jan-19 9:13:03 PM Sonos CheckIPAddressChange for UPnPDevice = Draagbaar found IPAddress =

        Jan-19 9:13:03 PM Sonos Reachable called for UPnPDevice Draagbaar which is not reachable but still on-line

        Jan-19 9:12:43 PM Sonos IPAddress for UPnPDevice = Draagbaar has changed. Old = 192.168.2.66. New =

        Jan-19 9:12:43 PM Sonos CheckIPAddressChange for UPnPDevice = Draagbaar found IPPort =

        Jan-19 9:12:43 PM Sonos CheckIPAddressChange for UPnPDevice = Draagbaar found IPAddress =

        Jan-19 9:12:43 PM Sonos Reachable called for UPnPDevice Draagbaar which is not reachable but still on-line

        Jan-19 9:12:32 PM Sonos MySSDP.RemoveDevices called with UDN = uuid:RINCON_000E58C6EE0801400

        Jan-19 9:12:32 PM Sonos MySSDP.RemoveDevices called with UDN = uuid:RINCON_000E58C6EE0801400

        Jan-19 9:12:32 PM Sonos MyUPnPDevices.Dispose called

        Thanks !

        Evja
        The PI needs to receive a period broadcast message ssdp:alive. If it doesn't it assumes the device is dead. So for whatever reason, this broadcast message (multicast actually) isn't coming through. This could be a firewall issue!!

        What you can do is to raise the UPNP debug level to verbose, turn the logging to disk ON (this will erase and open a new log file), wait an hour in which you should have seen the player go off-line and on-line again, turn the logging to disk off (this writes and closes the file), zip the file and email or post it. The debug disk log can be found at <hsroot>\html\MediaController\Logs\MediaControllerDebug.tx t

        Dirk

        Comment


          #5
          Hi Dirk,

          Enclosed is a homeseer log and the SonosDebug Log for a decent time window. Events start to occur around 6.27 pm. Both players (Draagbaar and Livingroom) drop and re-appear.

          The log was run with the windows firewall on the Win10 homeseer server completely turned OFF, just to be sure, although I did see the SSDP rules in there for both TCP and UDP.

          Hope you can figure it out

          Thanks,

          Evja
          Attached Files

          Comment


            #6
            Originally posted by evja78 View Post
            Hi Dirk,

            Enclosed is a homeseer log and the SonosDebug Log for a decent time window. Events start to occur around 6.27 pm. Both players (Draagbaar and Livingroom) drop and re-appear.

            The log was run with the windows firewall on the Win10 homeseer server completely turned OFF, just to be sure, although I did see the SSDP rules in there for both TCP and UDP.

            Hope you can figure it out

            Thanks,

            Evja
            uhh what happened to the debug log in .zip? It is unreadable and I see some _MACOSX subdirectory? Can you upload it without editing with anything?

            I'll have a look at the .doc file but I wouldn't keep my hopes up. I have a near 100% batting average when it comes to these kind of issue as being always network related.

            I'll have a look at it, there might always be a first case

            Dirk

            Comment


              #7
              Dirk, second attempt at the log

              This one is original file from longer period.

              Cheers !

              Evja
              Attached Files

              Comment


                #8
                Originally posted by evja78 View Post
                Dirk, second attempt at the log

                This one is original file from longer period.

                Cheers !

                Evja
                Excellent, this one is readable.
                Can you cut/paste the following URL in a browser and post the result

                http://192.168.2.65:1400/xml/group_description.xml

                Are all your players on the SAME and latest SW version?
                I just added a ZP90 to my setup, this player had been off-line for a while and as soon as it came on-line it caused havoc between all my players until I upgraded its SW. Seems stable now, trying to look at some of my logs to figure out what happened. The event on my network was quite severe actually.

                Second question, what kind is the portable player? Do you power it down on occasion? If so, are you disconnects correlated to it being powered up?

                Dirk

                Comment


                  #9
                  Dirk,

                  Output below:
                  <?xml version="1.0"?>

                  -<root xmlns="urn:schemas-upnp-org:device-1-0">


                  -<specVersion>

                  <major>1</major>

                  <minor>0</minor>

                  </specVersion>


                  -<device>

                  <deviceType>urn:smartspeaker-audio:device:SpeakerGroup:1</deviceType>

                  <friendlyName>Living Room</friendlyName>

                  <manufacturer>SONOS</manufacturer>

                  <UDN>uuid:RINCON_000E58A0E51A01400</UDN>


                  -<serviceList>


                  -<service>

                  <serviceType>urn:smartspeaker-audio:service:SpeakerGroup:1</serviceType>

                  <serviceId>urn:smartspeaker-audio:serviceId:SpeakerGroup</serviceId>

                  <controlURL>/ssdp/notfound</controlURL>

                  <eventSubURL>/ssdp/notfound</eventSubURL>

                  <SCPDURL>/ssdp/notfound</SCPDURL>

                  </service>

                  </serviceList>

                  </device>

                  </root>

                  Both are on same sw level 6.0 and same build no 31322220.
                  Portable is a Play 1 that has been online for days and is only powered down when moved, which it hasn't for over a week. This one is wireless (I also have a bridge in the network), the other ZP90 (Sonos Connect) is hard wired to the network. Both players display this behaviour.

                  Evja

                  Comment


                    #10
                    Originally posted by evja78 View Post
                    I also have a bridge in the network
                    Evja
                    Is the bridge hardwired or wireless connected?

                    Has the bridge been power cycled, perhaps power spikes?
                    If the wireless takes a hit, all you players take a hit, take it from me, that's how Sonos keep up with its own (RSTP) network in parallel with your network.

                    Dirk

                    Comment


                      #11
                      The bridge is hardwired and rarely gets power cycled. Not in recent weeks anyway.

                      Comment


                        #12
                        Can you post screenshots for:

                        1/ go to Sonos Config screen, need player table screenshot
                        2/ click on the "View Sonos Device", need that table

                        Can you post your Sonos.ini file

                        Do you see somewhere players with UDN xxxx_MS and xxx_MR? Perhaps in your homeseer device page?

                        Dirk

                        Comment


                          #13
                          Dirk, screenshots and ini included in zip.

                          I only see the master device and the 2 players in my devices list.
                          Attached Files

                          Comment


                            #14
                            The log shows why the PI disconnects, the alive event from the player is missing for some subdevices (I know, a bit too much info).

                            Why these alive events are missing... and for both players... is a bit beyond me because other alive events are showing up as they should.

                            Are these players disconnecting every hour and this goes on forever, or it works fine and then start disconnecting every hour and that goes on forever .... or it it comes and goes?

                            It is is always there .. or when it starts it always stays, does restarting the players help?

                            Dirk

                            Comment


                              #15
                              Hi Dirk,

                              I did a reboot of all devices (Connect, bridge and Play1) and a disable, re-enable of the plugin. The players are found and then start the usual behaviour after about an hour and consistently after that. See log below with a filter on Type=Sonos.

                              Jan-24 2:06:11 PM Sonos DirectConnect called for Zone Draagbaar with device name = uuid:RINCON_000E58C6EE0801400 and Model = S1

                              Jan-24 1:51:39 PM Sonos Disconnect: Disconnected from ZonePlayer - Draagbaar

                              Jan-24 1:51:19 PM Sonos IPAddress for UPnPDevice = Draagbaar has changed. Old = 192.168.2.66. New =

                              Jan-24 1:49:13 PM Sonos DirectConnect called for Zone Living Room with device name = uuid:RINCON_000E58A0E51A01400 and Model = ZP90

                              Jan-24 12:51:09 PM Sonos DirectConnect called for Zone Draagbaar with device name = uuid:RINCON_000E58C6EE0801400 and Model = S1

                              Jan-24 12:49:12 PM Sonos DirectConnect called for Zone Living Room with device name = uuid:RINCON_000E58A0E51A01400 and Model = ZP90

                              Jan-24 12:36:37 PM Sonos Disconnect: Disconnected from ZonePlayer - Draagbaar

                              Jan-24 12:36:17 PM Sonos IPAddress for UPnPDevice = Draagbaar has changed. Old = 192.168.2.66. New =

                              Jan-24 12:34:35 PM Sonos Disconnect: Disconnected from ZonePlayer - Living Room

                              Jan-24 12:34:15 PM Sonos IPAddress for UPnPDevice = Living Room has changed. Old = 192.168.2.65. New =

                              Jan-24 11:36:11 AM Sonos DirectConnect called for Zone Draagbaar with device name = uuid:RINCON_000E58C6EE0801400 and Model = S1

                              Jan-24 11:34:12 AM Sonos DirectConnect called for Zone Living Room with device name = uuid:RINCON_000E58A0E51A01400 and Model = ZP90

                              Jan-24 11:33:55 AM Sonos Disconnect: Disconnected from ZonePlayer - Draagbaar

                              Jan-24 11:33:53 AM Sonos IPAddress for UPnPDevice = Living Room has changed. Old = 192.168.2.65. New =

                              Jan-24 11:33:35 AM Sonos IPAddress for UPnPDevice = Draagbaar has changed. Old = 192.168.2.66. New =

                              Jan-24 10:34:16 AM Sonos CreateOneSonosController: Created instance of ZonePlayerController for Zoneplayer = Draagbaar with index 2

                              Jan-24 10:34:14 AM Sonos DirectConnect called for Zone Draagbaar with device name = uuid:RINCON_000E58C6EE0801400 and Model = S1

                              Jan-24 10:34:13 AM Sonos InitIO Called for Instance = RINCON_000E58C6EE0801400 and running on OS = Win32NT

                              Jan-24 10:34:13 AM Sonos CreateOneSonosController: Created instance of ZonePlayerController for Zoneplayer = Living Room with index 1

                              Jan-24 10:34:12 AM Sonos DirectConnect called for Zone Living Room with device name = uuid:RINCON_000E58A0E51A01400 and Model = ZP90

                              Jan-24 10:34:11 AM Sonos InitIO Called for Instance = RINCON_000E58A0E51A01400 and running on OS = Win32NT

                              Jan-24 10:33:30 AM Sonos Sonos Plugin Initialized

                              Looks like it is consistent behaviour ? An idea how to trace/pinpoint the offending subdevices ?

                              Thanks for your support !

                              Evja

                              Comment

                              Working...
                              X