Announcement

Collapse
No announcement yet.

Keeps restarting

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

    #16
    Originally posted by madas View Post
    OK - I just added this in and I will monitor. I notice my HS log is getting filled up with these entries immediately.


    Jan-04 12:24:39 PM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 215
    Jan-04 12:24:39 PM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 250
    Jan-04 12:24:39 PM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 259
    Jan-04 12:24:39 PM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 288
    Jan-04 12:24:38 PM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 370
    Jan-04 12:24:38 PM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 370
    Indeed. Will be interesting to see if we still receive after the event. It appears the PI gets an interrupt from the socket that it has received data and when the PI tries to read the data, it returns with an error. This typically signals that the socket got closed hence my original code to terminate; as I have no way (or coded anything ) to retry which could lead to endless retries if something else is wrong. So far you'd be the first that has this error and not surprisingly it happens on a "not so standard" setup. If this is just a transient error, I can fix it easily. If the socket somehow got corrupted not sure how easily I can recover from it or whether it is worth a lot of code for it.

    All .net and other Win10 related patches are installed for that VM image, correct?

    Dirk

    Comment


      #17
      oh yes - everything is up to date on the GUEST and HOST.

      will keep monitoring for the usual drop-out

      Comment


        #18
        Looks like it hasn't crashed since i installed this new version. Is that what you expected? I have a 10MB log file with these over and over and over

        1/4/2017 9:02:56 PM : successfully received more data for mcastAddress = 239.255.255.250 with bytes = 283
        1/4/2017 9:02:57 PM : successfully received more data for mcastAddress = 239.255.255.250 with bytes = 281
        1/4/2017 9:02:57 PM : successfully received more data for mcastAddress = 239.255.255.250 with bytes = 605
        1/4/2017 9:02:57 PM : successfully received more data for mcastAddress = 239.255.255.250 with bytes = 605
        1/4/2017 9:03:02 PM : successfully received more data for mcastAddress = 239.255.255.250 with bytes = 94
        1/4/2017 9:03:08 PM : successfully received more data for mcastAddress = 239.255.255.250 with bytes = 94
        1/4/2017 9:03:08 PM : successfully received more data for mcastAddress = 239.255.255.250 with bytes = 173

        Comment


          #19
          It looks like it has crashed now - no more events in the logs. It didn't restart itself this time either...


          an-05 8:43:54 AM Sonos Error Error in ReceiveCallback3 for mcastAddress = 239.255.255.250, RemoteEP = 239.255.255.250, RemoteEP.port = 1900, LocalIEP = 10.2.1.207, LocalIEP.Port = 1900 and Bytes read = 132; start receiving with error = An existing connection was forcibly closed by the remote host
          Jan-05 8:43:54 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 132
          Jan-05 8:43:54 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 137
          Jan-05 8:43:52 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 94
          Jan-05 8:43:49 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 372

          will send the full log.

          Comment


            #20
            Originally posted by madas View Post
            It looks like it has crashed now - no more events in the logs. It didn't restart itself this time either...


            an-05 8:43:54 AM Sonos Error Error in ReceiveCallback3 for mcastAddress = 239.255.255.250, RemoteEP = 239.255.255.250, RemoteEP.port = 1900, LocalIEP = 10.2.1.207, LocalIEP.Port = 1900 and Bytes read = 132; start receiving with error = An existing connection was forcibly closed by the remote host
            Jan-05 8:43:54 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 132
            Jan-05 8:43:54 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 137
            Jan-05 8:43:52 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 94
            Jan-05 8:43:49 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 372

            will send the full log.
            For a second I was very hopeful that the errors were benign but from the last log, it appears that after you received the last error, the socket is really dead.

            At this point, I suggest you revert to the official version in the updater. I'm about to jump on a plane to head to CES so I'm out until next week. Will noodle over how to add code to try to recover.

            Dirk

            Comment


              #21
              Thanks Dirk - have fun at CES!

              Comment


                #22
                Originally posted by madas View Post
                It looks like it has crashed now - no more events in the logs. It didn't restart itself this time either...


                an-05 8:43:54 AM Sonos Error Error in ReceiveCallback3 for mcastAddress = 239.255.255.250, RemoteEP = 239.255.255.250, RemoteEP.port = 1900, LocalIEP = 10.2.1.207, LocalIEP.Port = 1900 and Bytes read = 132; start receiving with error = An existing connection was forcibly closed by the remote host
                Jan-05 8:43:54 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 132
                Jan-05 8:43:54 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 137
                Jan-05 8:43:52 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 94
                Jan-05 8:43:49 AM 1 Sonos Error successfully received more data for mcastAddress = 239.255.255.250 with bytes = 372

                will send the full log.
                Appears I had already coded some recovery mechanism a few years back, it just didn't do what it was supposed to do.

                Try the attached, it will log errors each time it happens, not much I can do about it because the best solution is to find out why it fails in the first place.

                When the multicast listener craps out, it will restart within a minute. If you see it restarting every minute, we're even further up sh@tcreek than I had anticipated.

                Please post result after letting it run for a while.

                Dirk
                Last edited by dcorsus; January 9, 2017, 09:35 PM.

                Comment


                  #23
                  Running now - will report back when I see some drops. Do I need debug on or anything?

                  Comment


                    #24
                    Originally posted by madas View Post
                    Running now - will report back when I see some drops. Do I need debug on or anything?
                    Set UPNP logging to errors only.

                    Comment


                      #25
                      Hi Dirk

                      It hasn't restarted the plugin since the 9th (when I posted before). No errors in the logs at all

                      Any idea what that means? did you fix correct the problem?

                      G

                      Comment


                        #26
                        Originally posted by madas View Post
                        Hi Dirk

                        It hasn't restarted the plugin since the 9th (when I posted before). No errors in the logs at all

                        Any idea what that means? did you fix correct the problem?

                        G
                        I think there were at least 2 places where things didn't go as they should. One was when reading the input, it would error with zero bytes read. That was the most frequent error and I removed that, so you won't see those.

                        However, in the last log, it appeared that eventually the error would also show when the socket is instructed to be ready for the next incoming message and then die after that. This was less frequent and when this happens, you will see an error and some logging indicating that the socket is being restarted. Make sure you don't overlook it and do search on "ReceiveCallback3" in the log file.

                        Dirk

                        Comment


                          #27
                          Dirk,

                          I'll send you the log - but really there isn't much in it.

                          M

                          Comment


                            #28
                            Originally posted by madas View Post
                            Dirk,

                            I'll send you the log - but really there isn't much in it.

                            M
                            Looks good indeed

                            Comment


                              #29
                              If you are still seeing the error every minute, can you set the UPNP debug level to "ERROR ONLY". If you see no additional logging each minute, please restart the PI and wait until it happens again.
                              The log shows that at one point you lost communication with player kitchen but that got reestablished a few minutes later.
                              Interestingly enough, around the same time, we lose the multicast socket as well, so there is clearly something going on in the Ethernet stack. Either way, the PI tries to re-establish the multicast socket as coded but it continues to try, so without the UPNP log level setting, I can't tell whether it fails or there is just a bug in the code and it keeps on re-trying.
                              Dirk

                              Comment


                                #30
                                Hi Dirk,

                                The UPNP logging was already set to "ERRORS ONLY". Did you want me to chang e it to something else?

                                M

                                Comment

                                Working...
                                X