Announcement

Collapse
No announcement yet.

Started getting lots of network problems and communication failures.

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

    Started getting lots of network problems and communication failures.

    Bob,

    Has anything recently changed with network communications? I have started seeing a lot of issues with ISY subscription errors and missed status reports:

    Jun-21 00:06:29 ISYInsteon Restart : ->
    Jun-21 00:06:29 ISYInsteon Restart : Last message received before restart
    Jun-21 00:06:29 ISYInsteon Bottom of subscription thread loop
    Jun-21 00:06:29 ISYInsteon Attemp to close TcpClient
    Jun-21 00:06:29 ISYInsteon Read exited with False
    Jun-21 00:06:29 ISYInsteon read : The subscription connection to ISY has failed.


    Jun-21 00:06:49 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
    Jun-21 00:06:44 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
    Jun-21 00:06:38 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
    Jun-21 00:06:33 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
    Jun-21 00:06:29 ISYInsteon read : The subscription connection to ISY has failed.

    I haven't changed anything on the ISY and if I control devices from it everything works fine. I normally have to reboot the ISY and homeseer or the ISY plugin several times before I can get it to start working again. I don't seem to be having any issues with other devices on my network so I'm not sure where to look. I'm going to see if I can find an old version of the plugin to see if that corrects the issue. I'm currently on 3.0.1.6 and have seen the issue off and on for a bit, but it has been worse the last few days. Yesterday I had to cycle everything multiple times before I could get things working.

    Here is a snippet with debugging turned on just trying to turn a device on:


    Jun-21 00:35:08 ISYInsteon QueueLoop : Command for KPL Scenes/Dryer LED finished and removed from queue. Queue size = 1
    Jun-21 00:35:08 ISYInsteon Command Queue is now empty.
    Jun-21 00:35:08 ISYInsteon SetIOMulti : SetIOMulti set 86 to value 0
    Jun-21 00:35:08 ISYInsteon Add : Command for KPL Scenes/Dryer LED added to queue. Queue size = 1
    Jun-21 00:35:08 ISYInsteon Control : Exit control function
    Jun-21 00:35:08 ISYInsteon QueueLoop : Processing Command for KPL Scenes/Dryer LED. Queue size = 1
    Jun-21 00:35:08 ISYInsteon ProcessCommand : Sending DOF, to KPL Scenes/Dryer LED Attempt 0
    Jun-21 00:35:08 ISYInsteon Authorize : Authorize: encoding = "admin:xxx" to "YWRtaW46cWRwenl4"
    Jun-21 00:35:08 ISYInsteon SendRequest : Sending command [DOF431174 ]
    Jun-21 00:34:31 ISYInsteon read : ISY subscription: No data for 120 seconds, network problem?.
    Jun-21 00:34:28 ISYInsteon QueueLoop : Command for Basement/KPL NS (Light) finished and removed from queue. Queue size = 1
    Jun-21 00:34:28 ISYInsteon Command Queue is now empty.
    Jun-21 00:34:28 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
    Jun-21 00:34:23 ISYInsteon CheckDeviceStatus : Comparing 255 with 0
    Jun-21 00:34:23 ISYInsteon ProcessCommand : Sending DON, 255 to Basement/KPL NS (Light) Attempt 4
    Jun-21 00:34:23 ISYInsteon Authorize : Authorize: encoding = "admin:xxx" to "YWRtaW46cWRwenl4"
    Jun-21 00:34:23 ISYInsteon SendRequest : Sending command [DON25534 DE 4E 10 ]
    Jun-21 00:34:22 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
    Jun-21 00:34:17 ISYInsteon CheckDeviceStatus : Comparing 255 with 0
    Jun-21 00:34:17 ISYInsteon ProcessCommand : Sending DON, 255 to Basement/KPL NS (Light) Attempt 3
    Jun-21 00:34:17 ISYInsteon Authorize : Authorize: encoding = "admin:xxx" to "YWRtaW46cWRwenl4"
    Jun-21 00:34:17 ISYInsteon SendRequest : Sending command [DON25534 DE 4E 10 ]
    Jun-21 00:34:17 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
    Jun-21 00:34:12 ISYInsteon CheckDeviceStatus : Comparing 255 with 0
    Jun-21 00:34:12 ISYInsteon ProcessCommand : Sending DON, 255 to Basement/KPL NS (Light) Attempt 2
    Jun-21 00:34:12 ISYInsteon Authorize : Authorize: encoding = "admin:xxx" to "YWRtaW46cWRwenl4"
    Jun-21 00:34:12 ISYInsteon SendRequest : Sending command [DON25534 DE 4E 10 ]
    Jun-21 00:34:12 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
    Jun-21 00:34:07 ISYInsteon CheckDeviceStatus : Comparing 255 with 0
    Jun-21 00:34:07 ISYInsteon ProcessCommand : Sending DON, 255 to Basement/KPL NS (Light) Attempt 1
    Jun-21 00:34:07 ISYInsteon Authorize : Authorize: encoding = "admin:xxx" to "YWRtaW46cWRwenl4"
    Jun-21 00:34:07 ISYInsteon SendRequest : Sending command [DON25534 DE 4E 10 ]
    Jun-21 00:34:07 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
    Jun-21 00:34:02 ISYInsteon CheckDeviceStatus : Comparing 255 with 0
    Jun-21 00:34:01 ISYInsteon SetIOMulti : SetIOMulti set 1704 to value 100
    Jun-21 00:34:01 ISYInsteon Add : Command for Basement/KPL NS (Light) added to queue. Queue size = 1
    Jun-21 00:34:01 ISYInsteon Control : Exit control function
    Jun-21 00:34:01 ISYInsteon QueueLoop : Processing Command for Basement/KPL NS (Light). Queue size = 1
    Jun-21 00:34:01 ISYInsteon ProcessCommand : Sending DON, 255 to Basement/KPL NS (Light) Attempt 0
    Jun-21 00:34:01 ISYInsteon Authorize : Authorize: encoding = "admin:xxx" to "YWRtaW46cWRwenl4"
    Jun-21 00:34:01 ISYInsteon SendRequest : Sending command [DON25534 DE 4E 10 ]
    Jun-21 00:33:34 ISYInsteon Logging to HomeSeer Log Enabled.

    Thanks,
    Jeff

    #2
    [QUOTE=cerjzc;1371187]Bob,

    Has anything recently changed with network communications? I have started seeing a lot of issues with ISY subscription errors and missed status reports:
    /QUOTE]

    That part of the plug-in has been unchanged since the ISY 5.x alpha software added something called TCP chunking and some changes were needed to handle that properly. That change was made over a year ago.

    Both issues you're seeing are related. The plug-in opens a network connection to the ISY (A subscription) that is a one-way ISY->plug-in communication. The plug-in just listens and processes all the messages the ISY sends over that connection.

    The ISY should be sending a "heartbeat" type message every minute or so in addition to any status updates or configuration changes.

    What you're seeing is what happens when the plug-in doesn't receive anything for a few minutes. At that point, it thinks something happened to the connection so it closes it and re-opens it. That's the connection failure and restarts.

    Sending command to the ISY opens a network connection just to send that command. When you send a command that should cause something to change, the plug-in waits for a bit for the ISY to send a notification of the change (on the subscription connection above). If it doesn't see a response, it will retry a few times.

    There have a been a couple of other reports like this but it's not really something that can be debugged from the plug-in's side. It's very hard for the receiver to determine why it didn't get something.

    If this is a persistent issues, then we should get UDI involved and maybe open a ticket with them. The ISY logs may provide a clue, but I'm not familiar with the ISY error codes and messages.
    --
    Bob Paauwe
    ISYInsteon Plug-in
    http://www.bobsplace.com/ISYInsteon/

    Comment


      #3
      Thanks Bob,

      After posting last night I did try rolling back to an older version and spent some more time moving the ISY to another IP and switched it from a static IP to DHCP with a reservation. I have been running the most recent of the 5.12 ISY alpha roughly since it was released so that hasn't changed recently either. I had seen the issue from time to time in the past, but normally it was when something rebooted or a power glitch. The issue now is once it starts happening I have real trouble getting things working again and have to reboot/restart everything multiple times before it stops logging the errors. I'm also going to try moving which switch the ISY is on and replacing the network cable just in case. I also don't know if it started around the time of the last windows 10 updates or not, but will check although I have confirmed the windows network settings and firewall are off.

      If I do need to post to UDI is there a specific term for this communication or is it just called a heartbeat do you happen to know?

      Thanks,
      Jeff

      Comment


        #4
        Since it's happening so frequently, that's actually helps for debugging and we can try a couple of things to get more information.

        If it's actually running OK right now, don't try this until it has problems again.

        If you set the plug-in's logging (from the configuration - logging/debugging tab) to "Status" level and "Debug Console" and the put HomeSeer in "Developer Mode" by checking the check box by that name on the manage plug-in screen you'll get a windows CMD window opened when the plug-in starts and that will have all the start up messages & errors logged. I'm assuming from your description that you start seeing the subscription fail/restart fairly soon after the plug-in starts?

        On initial startup, the plug-in does a number of queries to the ISY to get information and I'm curios to know if any of those are failing or if it's just the subscription connection.

        The specific term would be subscription connection.
        --
        Bob Paauwe
        ISYInsteon Plug-in
        http://www.bobsplace.com/ISYInsteon/

        Comment


          #5
          You are correct when the problem has been happening it starts right away and the last few times I had to cycle things multiple times to get it working again. I will wait until it occurs again and follow your instructions to see if it gives any clues.

          Thanks,
          Jeff

          Comment


            #6
            Having the same problem. Loss of communication

            Bob,


            I'm having a similar issue and it started after the last update a few days ago. I'm able to communicate with the ISY using Mobilinc and other apps with no issues. The plug-in is not able to stay connected and constantly restarting. I know via ping tests that the ISY isn't disappearing off the network and cold reboots of HS3 system and ISY do not resolve.

            The log file is filled with:

            ISYInsteon read : ISY subscription: No data for 120 seconds, network problem?.

            ISYInsteon Version3.0.1.6
            ISY:ISY 994i 1024 IR
            ISY Firmware:4.6.2
            Last edited by rlrjupiter; June 23, 2018, 12:47 AM. Reason: formating

            Comment


              #7
              There's clearly something going on but I don't yet have a clue as to what. There are now I think 4 reports of this.

              I'm not seeing this and the code where this is happening hasn't changed in over a year so it's going to take some detective work to figure out why this is happening.

              If/When this issue is happening, capturing the initial plug-in startup log is probably the first step. In the post above I explain how to get this to a windows cmd window. At this point, a full debug log would be best. *** be aware that debug logs can contain your ISY username/password so don't post those here. Either scrub them or send the log directly to me (I have way too many passwords to remember so I don't even want to see yours, it will just confuse me )

              Also, the following info may help track down what's triggering this:

              1) What OS and OS version are you running HomeSeer on?

              2) What version were you running previously?
              --
              Bob Paauwe
              ISYInsteon Plug-in
              http://www.bobsplace.com/ISYInsteon/

              Comment


                #8
                Communication loss

                Strange thing is it seems to be populating the HS3 device list on startup. I'll get as much log info as I can and send to you. Darn W10 is constantly updating so not sure what might have changed there, but I did let your plugin update right before the problem started.

                I don't use the homeseer portal, but do use the ISY portal with ALEXA. There was a recent change on that portal, just not sure if related by interfering with normal ISY operation.

                thanks, data to follow.

                Comment


                  #9
                  Mine hasn't acted up again yet so I haven't played with the debug setting, but maybe we need to report in on HS version and OS version. I wonder if it is one of the newer HS beta's or maybe in the OS and an update that triggered it.

                  I'm on the current beta of HS which I think is .449 and I'm on Windows 10 and the current Feature release with all patches. I'm not sure if it maybe started after the last update of windows or after the .445 or .449 beta of HS.

                  If the others seeing this can report in maybe we can come up with a pattern.

                  Jeff

                  Comment


                    #10
                    communication loss logs

                    I'm not using any beta versions.
                    My windows version is:
                    Windows 10 pro ver 1703 build 15063.1112
                    Attached is list of recent windows updates.

                    Bob, I'll send you everything I could find in a zip file. ISY log, startup log, plugin debug log and such.

                    Thanks, I'm really missing my HS3 & ISY link and voice feedback.
                    Attached Files

                    Comment


                      #11
                      communication loss logs

                      I'm not using any beta versions.
                      My windows version is:
                      Windows 10 pro ver 1703 build 15063.1112
                      Attached is list of recent windows updates.

                      Bob, I'll send you everything I could find in a zip file. ISY log, startup log, plugin debug log and such.

                      Thanks, I'm really missing my HS3 & ISY link and voice feedback.

                      Comment


                        #12
                        Well it was still working fine, but for some reason the HS log had stop updating even though Ultralog was still working. So I decided to move back to the current version of the ISY plugin and cycle Homeseer. I set the logging to status and turned on Developer mode, but I don't think it will be much help:

                        Dev log:

                        Plugin: ISYInsteon Instance: 3.0.1.6 starting...
                        ISYInsteon Connecting to server at 127.0.0.1...
                        Watchdog thread timeout: 600 seconds.
                        Creating isy class instance: [192.168.0.116]
                        Checking service type: urn:udi-com:service:X_Insteon_Lighting_Service:1
                        Checking service type: UDIELKWebServices
                        Skipping [/elkServices.wsdl]
                        Skipping [/security/elk]
                        Checking service type: UDISEPWebServices
                        Skipping [/sepServices.wsdl]
                        Skipping [/sepServices]
                        Checking service type: UDIZWaveWebServices
                        Skipping [/zwaveServices.wsdl]
                        Skipping [/zwaveServices]
                        Watchdog thread started for 600 seconds.
                        Connected to HomeSeer at ip address 127.0.0.1
                        Host API version = 3 HomeSeer 3.0.0.449 (4)
                        Callback API version = 3
                        ISYInsteon Registered.
                        ISYInsteon Connected, waiting to be initialized...


                        The logging in HS showed:

                        Jun-24 18:24:05 ISYInsteon Command Queue is now empty.
                        Jun-24 18:24:02 ISYInsteon Command Queue is now empty.
                        Jun-24 18:24:02 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
                        Jun-24 18:23:57 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
                        Jun-24 18:23:52 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
                        Jun-24 18:23:46 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
                        Jun-24 18:23:41 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
                        Jun-24 18:23:36 ISYInsteon Command Queue is now empty.
                        Jun-24 18:23:36 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
                        Jun-24 18:23:31 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
                        Jun-24 18:23:26 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
                        Jun-24 18:23:20 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
                        Jun-24 18:23:15 ISYInsteon ProcessCommand : ISY network communication failure: missed status report for device Basement/KPL NS (Light). (34 DE 4E 1)
                        Jun-24 18:23:15 ISYInsteon read : ISY subscription: No data for 120 seconds, network problem?.
                        Jun-24 18:21:14 ISYInsteon read : ISY subscription: No data for 120 seconds, network problem?.
                        Jun-24 18:21:00 ISYInsteon Command Queue is now empty.
                        Jun-24 18:19:38 ISYInsteon Command Queue is now empty.
                        Jun-24 18:19:14 ISYInsteon Device record verification complete.
                        Jun-24 18:19:14 ISYInsteon ISYInsteon Plug-in initialization complete.
                        Jun-24 18:19:11 ISYInsteon Verifying HomeSeer device records, this may take a while.
                        Jun-24 18:19:10 ISYInsteon RESTQueryVariableNames : --> Data at the root level is invalid. Line 1, position 1.
                        Jun-24 18:19:10 ISYInsteon RESTQueryVariableNames : REST variable query failed. Corrupteded XML?
                        Jun-24 18:19:10 ISYInsteon Found 2 integer variables
                        Jun-24 18:19:10 ISYInsteon Modules installed on ISY:
                        Jun-24 18:19:10 ISYInsteon + 21010 OpenADR
                        Jun-24 18:19:08 ISYInsteon ISY Firmware version: 5.0.12
                        Jun-24 18:19:08 ISYInsteon I have connected to HS

                        Now I will have to try to get it working again by restarting everything a few times. Twice I have had to reboot my router for some reason and then it will start connecting again. I'm going to also try swapping ports on the switch and the cable now to see if that does anything.

                        Jeff

                        Comment


                          #13
                          Well just as a follow up to my own post. I swapped the cable and the switch port which didn't seem to help. I rebooted the ISY and the plugin multiple times, but still couldn't get it to work. So then I tried rebooting the computer with Homeseer on it and the ISY again at the same time. After that when it came back up it finally reconnected and started working again.

                          Will wait and see the next time it happens.

                          Jeff

                          Comment


                            #14
                            Originally posted by cerjzc View Post
                            I set the logging to status and turned on Developer mode, but I don't think it will be much help:

                            Jun-24 18:19:10 ISYInsteon RESTQueryVariableNames : --> Data at the root level is invalid. Line 1, position 1.
                            Jun-24 18:19:10 ISYInsteon RESTQueryVariableNames : REST variable query failed. Corrupteded XML?
                            This may or may not mean something. Do you have any state variables defined? If so, then the ISY is sending bad data here, before the subscription connection fails.
                            --
                            Bob Paauwe
                            ISYInsteon Plug-in
                            http://www.bobsplace.com/ISYInsteon/

                            Comment


                              #15
                              Originally posted by cerjzc View Post
                              Well just as a follow up to my own post. I swapped the cable and the switch port which didn't seem to help. I rebooted the ISY and the plugin multiple times, but still couldn't get it to work. So then I tried rebooting the computer with Homeseer on it and the ISY again at the same time. After that when it came back up it finally reconnected and started working again.

                              Will wait and see the next time it happens.

                              Jeff
                              So rebooting the computer helped.

                              Are you running the admin console on this same computer and if so do you have it always running?
                              --
                              Bob Paauwe
                              ISYInsteon Plug-in
                              http://www.bobsplace.com/ISYInsteon/

                              Comment

                              Working...
                              X