Announcement

Collapse
No announcement yet.

Periodically get "Unable to communicate with Insteon powerline interface"

Collapse
This topic is closed.
X
X
 
  • Filter
  • Time
  • Show
Clear All
new posts

    Periodically get "Unable to communicate with Insteon powerline interface"

    Recently I have been receiving the message below on Insteon Plugin configuration page. It loses connection with the Insteon Hub and requires a Insteon Plugin reboot. It seems like it is once a day and requires me to restart the plugin. It may have coincided with a recent HS3 update (3.0.0.435). I have not tracked down a corresponding log message, but I will try.

    Can you provide me with some options to have a more stable system? Your self healing post can automate enabling/disabling the plugin, which is handy. However I would first like to make some attempts at stabilizing the HS3/Insteon plugin/network.

    Log message inside plugin:
    ** Unable to communicate with the Insteon powerline interface ***
    Please make sure the interface is configured correctly and restart the plug-in.

    HS3 Pro Edition 3.0.0.435
    Insteon plugin v3.0.6.0.32

    #2
    there are a couple of parameters you can tweak by adding the following to the insteon.ini (you must shutdown the plugin before changing the ini file). Try just adding the GetXMLBufferInterval first

    [Hub]
    ResponseTime=3
    GetXMLBufferInterval=2000

    ResponseTime (seconds) - how long the plugin will wait for a response
    GetXMLBufferInterval (msecs) - how frequently the plugin will poll the hub for new inbound messages. 2000 is the default; try a larger number
    Mark

    HS3 Pro 4.2.19.5
    Hardware: Insteon Serial PLM | AD2USB for Vista Alarm | HAI Omnistat2 | 1-Wire HA7E | RFXrec433 | Dahua Cameras | LiftMaster Internet Gateway | Tuya Smart Plugs
    Plugins: Insteon (mine) | Vista Alarm (mine) | Omnistat 3 | Ultra1Wire3 | RFXCOM | HS MyQ | BLRadar | BLDenon | Tuya | Jon00 Charting | Jon00 Links
    Platform: Windows Server 2022 Standard, i5-12600K/3.7GHz/10 core, 16GB RAM, 500GB SSD

    Comment


      #3
      Log capture of the issue

      It crashed again overnight , so I grabbed the recent log messages below. The “Unable to communicate” message is again present in the Insteon Plugin configuration screen. Can you answer a few questions to help me understand the situation?

      -Do these “My XML buffer” reveal some type of issue? The system has worked perfectly for the last 2 months, so can you hypothesis what has changed (i.e. HS3 update)?

      -Will GetXMLBufferInterval solve this issue? I have extremely powerful HS3 hardware (Intel 8th gen) and little network traffic (Rebooted everything), so why would this be an issue now?

      -Why does the average amount of data in the buffer seem to increase over time?

      -Why the first message “Log maintenance needed”? The max size is set to 50MB, and HomeSeerLog.hsd is only 400KB.

      Log Snippets:
      May-04 7:45:31 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-04 7:45:31 AM Insteon ..My XML buffer: 02604B77930333A30602604B77930333A30602604B77930333A30602503E 39B7000001CF13001502151502503E40D3000001CF130002503E40D30001 01CB130102503E40D3130001C7060015027F0206027F02061515027F0006 027F0206027F000602503E3FBD000101CF110102503E3FBD110001CF0600 0250435085000001CF11000250435085000101CF110115151515027F0206 1515151515151502503E411B000101CB110102503E411B110001CB060002 50404FE6000001CF11000250404FE6000101CF11010250404FE6110001CF 06000250404FE6130001CF060002503E44EA000101CF110102503E44EA11 0001CF060002503E44EA000001CF130002503E44EA000101CF1301150250 366355000101C711010250366355110001CF06000250435085000001CF11 000250435085000101CF11010250435085110001CF06000250404FB90001 01CB11010250404FB9110001CF06000250423ED9000101CF11010250423E D9110001CF060002503E40D3000001CF110002503E40D3000101C7110102 503E40D3110001CB060002503E44EA000001CF13000250423ED9000001CF 11000250423ED9000101CF11010250423ED9110001CF06000250423ED900 0001CB13000250423ED9000101CF13010250423ED9130001CF0600025042 3ED9000001CF11000250423ED9000101CB11010250423ED9110001CF0600 0250423ED9000001CF1300025040C59E000001CF1100025040C59E000101 CB110015150250404FE6000001CF11000250404FE6000101CF1101025040 4FE6110001CF060002503E3D56000001CF110002503E3D56000101CF1101 02503E3D56110001CB060002503E3D56000001CF1300025040506C000001 CF1300025040506C130001CF06000250404FB9000006CF11000250404FB9 000106CF11060250404FB9000206CF11060250404FB9110006CB06000250 423ED9000001CF13000250423ED9000101CF13010250423ED9130001CF06 00025040C59E000001CF13000250435085000001CF130002504350850001 01CF13010250435085130001CF06000250435085000101CF110102504350 85110001CF0600025040C59E000001CF1100025040C59E000101CF110102 5040C59E110001CF06001515027F00060250423ED9000001CF1100025042 3ED9000101CF11010250423ED9110001CF0600
      May-04 7:45:31 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-04 7:45:31 AM Insteon ..My XML buffer: 1515151502604B77930333A30602604B77930333A3061502604B77930333 A30602503E39B7000001CF13001502151502503E40D3000001CF13000250 3E40D3000101CB130102503E40D3130001C7060015027F0206027F020615 15027F0006027F0206027F000602503E3FBD000101CF110102503E3FBD11 0001CF06000250435085000001CF11000250435085000101CF1101151515 15027F0206027F00061515151515151502503E411B000101CB110102503E 411B110001CB06000250404FE6000001CF11000250404FE6000101CF1101 0250404FE6110001CF06000250404FE6130001CF060002503E44EA000101 CF110102503E44EA110001CF060002503E44EA000001CF130002503E44EA 000101CF1301150250366355000101C711010250366355110001CF060002 50435085000001CF11000250435085000101CF11010250435085110001CF 06000250404FB9000101CB11010250404FB9110001CF06000250423ED900 0101CF11010250423ED9110001CF060002503E40D3000001CF110002503E 40D3000101C7110102503E40D3110001CB060002503E44EA000001CF1300 0250423ED9000001CF11000250423ED9000101CF11010250423ED9110001 CF06000250423ED9000001CB13000250423ED9000101CF13010250423ED9 130001CF06000250423ED9000001CF11000250423ED9000101CB11010250 423ED9110001CF06000250423ED9000001CF1300025040C59E000001CF11 00025040C59E000101CB110015150250404FE6000001CF11000250404FE6 000101CF11010250404FE6110001CF060002503E3D56000001CF11000250 3E3D56000101CF110102503E3D56110001CB060002503E3D56000001CF13 00025040506C000001CF1300025040506C130001CF06000250404FB90000 06CF11000250404FB9000106CF11060250404FB9000206CF11060250404F B9110006CB06000250423ED9000001CF13000250423ED9000101CF130102 50423ED9130001CF0600025040C59E000001CF13000250435085000001CF 13000250435085000101CF13010250435085130001CF0600025043508500 0101CF11010250435085110001CF0600025040C59E000001CF1100025040 C59E000101CF1101025040C59E110001CF06001515027F00060250423ED9 000001CF11000250423ED9000101CF11010250423ED9110001CF0600
      May-04 7:43:36 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1

      …. Much of the same type of messages with a burst of messages about every 5 minutes.
      …. “Device Control” command below failed to turn on light.

      May-04 6:39:17 AM Insteon ..My XML buffer: 02503E40D3000001CF110002503E39B7000101CF13010250404E60000101 CF1301151515151515150250404FE6000001CF11000250404FE6000101CF 11010250404FE6110001CF06000250404FE6000001CF1300025043508500 0001CF1300027F0006151515021515025040506C000001CF110002504050 6C000101CF1101025040506C110001CF0600
      May-04 6:39:05 AM Device Control Device: Game room Light to On (100) by/from: CAPI Control Handler
      May-04 6:38:54 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-04 6:38:54 AM Insteon ..My XML buffer: 1515151502604B77930333A30602604B77930333A3061502604B77930333 A30602503E39B7000001CF13001502151502503E40D3000001CF13000250 3E40D3000101CB130102503E40D3130001C7060015027F0206027F020615 15027F0006027F0206027F000602503E3FBD000101CF110102503E3FBD11 0001CF06000250435085000001CF11000250435085000101CF1101151515 15027F0206027F00061515151515151502503E411B000101CB110102503E 411B110001CB06000250404FE6000001CF11000250404FE6000101CF1101 0250404FE6110001CF0600
      May-04 6:38:54 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1

      …. The last “Device Control” command, of the evening, below was successful.

      May-03 11:12:52 PM Insteon ..My XML buffer: 1502604B77930333A30602604B77930333A30602503E40D3000001CF1100 0250404E60000101CF1301
      May-03 11:12:47 PM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-03 11:12:47 PM Insteon ..My XML buffer: 1502604B77930333A3060250404E60000001CF1300
      May-03 11:12:47 PM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-03 11:12:47 PM Insteon ..My XML buffer: 1515151502604B77930333A3060250404E60000001CF1300
      May-03 11:11:06 PM Device Control Device: Good night scene to Off (2) by/from: CAPI Control Handler
      May-03 11:11:02 PM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-03 11:11:02 PM Insteon ..My XML buffer: 15151502503E40D3000101CF110102503E40D3110001CB060002503E39B7 130001CF0600
      May-03 11:11:02 PM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-03 11:11:02 PM Insteon ..My XML buffer: 1502604B77930333A30602503E40D3000001CF110002503E39B7000101CF 1301
      May-03 11:11:02 PM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-03 11:11:02 PM Insteon ..My XML buffer: 02503E40D3000001CF110002503E39B7000101CF1301
      May-03 11:11:01 PM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-03 11:11:01 PM Insteon ..My XML buffer: 02604B77930333A30602604B77930333A30602604B77930333A30602503E 39B7000001CF1300
      May-03 11:11:01 PM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-03 11:11:01 PM Insteon ..My XML buffer: 1515151502604B77930333A30602604B77930333A3061502604B77930333 A30602503E39B7000001CF1300
      May-03 11:06:09 PM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-03 11:06:09 PM Insteon ..My XML buffer: 15151502503E40D3000101CF110102503E40D3110001CB0600
      May-03 11:06:08 PM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-03 11:06:08 PM Insteon ..My XML buffer: 1502604B77930333A30602604B77930333A30602503E40D3000001CF1100
      May-03 11:06:08 PM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-03 11:06:08 PM Insteon ..My XML buffer: 1502604B77930333A30602503E40D3000001CF1100
      May-03 11:06:08 PM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
      May-03 11:06:08 PM Insteon ..My XML buffer: 02503E40D3000001CF1100
      May-03 10:55:00 PM Log Warning Log database maintenance may be needed. (283 >= 50)

      Comment


        #4
        the xml buffer should only be about 100 characters at a time. there is a lot of inbound insteon traffic which is flooding the hub.

        the following byte stream is in the buffer a lot 02604B77930333A306

        what is device 04:B7:79?

        i would suggest searching through these buffer entries for other insteon devices and see if there are one or two device sending unnecessary commands.

        every 5 minutes might indicate something related to a run away event

        if all else fails, you might try a reset and reprogram on the interface hub from the plugin config page
        Mark

        HS3 Pro 4.2.19.5
        Hardware: Insteon Serial PLM | AD2USB for Vista Alarm | HAI Omnistat2 | 1-Wire HA7E | RFXrec433 | Dahua Cameras | LiftMaster Internet Gateway | Tuya Smart Plugs
        Plugins: Insteon (mine) | Vista Alarm (mine) | Omnistat 3 | Ultra1Wire3 | RFXCOM | HS MyQ | BLRadar | BLDenon | Tuya | Jon00 Charting | Jon00 Links
        Platform: Windows Server 2022 Standard, i5-12600K/3.7GHz/10 core, 16GB RAM, 500GB SSD

        Comment


          #5
          Mine gets into that state every few days as well.

          In the config directory there are a bunch of "Insteon Error Report [Date]" files, and the last few all have this exception:

          Error: Error in Hub.GetBuffer: The request was aborted: The operation has timed out. -- Details System.Net.WebException: The request was aborted: The operation has timed out.
          at System.Net.HttpWebRequest.GetResponse()
          at System.Xml.XmlDownloadManager.GetNonFileStream(Uri uri, ICredentials credentials, IWebProxy proxy, RequestCachePolicy cachePolicy)
          at System.Xml.XmlDownloadManager.GetStream(Uri uri, ICredentials credentials, IWebProxy proxy, RequestCachePolicy cachePolicy)
          at System.Xml.XmlUrlResolver.GetEntity(Uri absoluteUri, String role, Type ofObjectToReturn)
          at System.Xml.XmlTextReaderImpl.FinishInitUriString()
          at System.Xml.XmlTextReaderImpl..ctor(String uriStr, XmlReaderSettings settings, XmlParserContext context, XmlResolver uriResolver)
          at System.Xml.XmlReaderSettings.CreateReader(String inputUri, XmlParserContext inputContext)
          at System.Xml.XmlReader.Create(String inputUri, XmlReaderSettings settings, XmlParserContext inputContext)
          at Insteon.Support.Hub.SocketPortClass.GetBuffer() -- 4/26/2018 12:00:26 PM


          Would a try/catch construct around SockPortClass.GetBuffer fix this?

          Comment


            #6
            Originally posted by NateW View Post
            Mine gets into that state every few days as well.

            In the config directory there are a bunch of "Insteon Error Report [Date]" files, and the last few all have this exception:

            Error: Error in Hub.GetBuffer: The request was aborted: The operation has timed out. -- Details System.Net.WebException: The request was aborted: The operation has timed out.
            at System.Net.HttpWebRequest.GetResponse()
            at System.Xml.XmlDownloadManager.GetNonFileStream(Uri uri, ICredentials credentials, IWebProxy proxy, RequestCachePolicy cachePolicy)
            at System.Xml.XmlDownloadManager.GetStream(Uri uri, ICredentials credentials, IWebProxy proxy, RequestCachePolicy cachePolicy)
            at System.Xml.XmlUrlResolver.GetEntity(Uri absoluteUri, String role, Type ofObjectToReturn)
            at System.Xml.XmlTextReaderImpl.FinishInitUriString()
            at System.Xml.XmlTextReaderImpl..ctor(String uriStr, XmlReaderSettings settings, XmlParserContext context, XmlResolver uriResolver)
            at System.Xml.XmlReaderSettings.CreateReader(String inputUri, XmlParserContext inputContext)
            at System.Xml.XmlReader.Create(String inputUri, XmlReaderSettings settings, XmlParserContext inputContext)
            at Insteon.Support.Hub.SocketPortClass.GetBuffer() -- 4/26/2018 12:00:26 PM


            Would a try/catch construct around SockPortClass.GetBuffer fix this?
            Nate,
            thanks for the suggestion. the routine is wrapped in a try/catch. I just display the full error in the log for my purposes.

            did you try the ini setting above in your setup? also, the beta 3.0.6.34 contains some improvements for the hub. please try and report back.
            Mark

            HS3 Pro 4.2.19.5
            Hardware: Insteon Serial PLM | AD2USB for Vista Alarm | HAI Omnistat2 | 1-Wire HA7E | RFXrec433 | Dahua Cameras | LiftMaster Internet Gateway | Tuya Smart Plugs
            Plugins: Insteon (mine) | Vista Alarm (mine) | Omnistat 3 | Ultra1Wire3 | RFXCOM | HS MyQ | BLRadar | BLDenon | Tuya | Jon00 Charting | Jon00 Links
            Platform: Windows Server 2022 Standard, i5-12600K/3.7GHz/10 core, 16GB RAM, 500GB SSD

            Comment


              #7
              I set HubResponseTime=3 last night, and the Insteon plugin was broken today. I'm adding GetXMLBufferInterval=2000 now, will keep an eye on it for the next few days.

              Is the timeout what causes the plug in to get into that broken state? And if so, is there a way to just restart the plugin when the exception is caught? Or better yet, handle the exception gracefully and continue rather than restarting.

              Or better still, catch IOException so the plugin can recover from any communication-related exception.

              Comment


                #8
                Originally posted by NateW View Post
                I set HubResponseTime=3 last night, and the Insteon plugin was broken today. I'm adding GetXMLBufferInterval=2000 now, will keep an eye on it for the next few days.

                Is the timeout what causes the plug in to get into that broken state? And if so, is there a way to just restart the plugin when the exception is caught? Or better yet, handle the exception gracefully and continue rather than restarting.

                Or better still, catch IOException so the plugin can recover from any communication-related exception.
                Nate,
                the plugin has several different exception handling routines built into GetBuffer.

                I've never been about to reproduce many of these errors in my test environment so its difficult to resolve.
                Mark

                HS3 Pro 4.2.19.5
                Hardware: Insteon Serial PLM | AD2USB for Vista Alarm | HAI Omnistat2 | 1-Wire HA7E | RFXrec433 | Dahua Cameras | LiftMaster Internet Gateway | Tuya Smart Plugs
                Plugins: Insteon (mine) | Vista Alarm (mine) | Omnistat 3 | Ultra1Wire3 | RFXCOM | HS MyQ | BLRadar | BLDenon | Tuya | Jon00 Charting | Jon00 Links
                Platform: Windows Server 2022 Standard, i5-12600K/3.7GHz/10 core, 16GB RAM, 500GB SSD

                Comment


                  #9
                  Still have issues

                  Still struggling and again the system was working great for 4 months. When I try turning on any light (Tried several), from Homeseer Home View, I get a log similiar to below. The light actually does come on, but it takes about 30 seconds (i.e. 6:13:26 AM). Can you explain the log entries "Retry #", "Internal transmit attempt failed", My XML buffer: 15151515", and "Pausing 250ms for Hub to clear".

                  Devices involved:
                  Insteon Hub: 4E.77.93
                  Kitchen Breakfast light: 42.3A.90 (Located 6ft from Hub)

                  Software versions:
                  HS3 version: HS3 Pro Edition 3.0.0.435 (Windows)
                  Insteon Plugin version: 3.0.6.34
                  Insteon Thermostat: 3.0.6.3 (Disabled)

                  Things I have tried (Including suggestions):
                  -Reboot every part of system many times
                  -Use latest version of Insteon Plugin
                  -Reprogram the Insteon Hub using Plugin (~200 links)
                  -Added "[Hub] GetXMLBufferInterval=4000 ResponseTime=5" to Insteon.ini
                  -Disabled Insteon Thermostat Plugin
                  -All events have manually been disabled
                  -Removed Jon00Alexa scripts

                  Captured log (Turn on kitchen breakfast light from Hub):
                  May-09 6:13:26 AM Insteon Received a Direct ACK from Kitchen Breakfast light (42.3A.90): 42 3A 90 4B 77 93 2A 11 FF
                  May-09 6:13:26 AM Insteon Received STX 0x50 (Raw Insteon Rec):42 3A 90 4B 77 93 2A 11 FF
                  May-09 6:13:26 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
                  May-09 6:13:26 AM Insteon ..My XML buffer: 0250423A904B77932A11FF
                  May-09 6:13:18 AM Insteon Setting status and value for device 42.3A.90:1. Old status:0 Old Value:0, New Status:2 New Value:100
                  May-09 6:13:18 AM Insteon ..Got Hub Response 02 62 42 3A 90 0A 11 FF 06
                  May-09 6:13:18 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
                  May-09 6:13:18 AM Insteon ..My XML buffer: 0262423A900A11FF06
                  May-09 6:13:14 AM Insteon Sending http://192.168.1.128:25105/3?0262423A900A11FF=I=3
                  May-09 6:13:14 AM Insteon Received a Direct ACK from Kitchen Breakfast light (42.3A.90): 42 3A 90 4B 77 93 2A 11 FF
                  May-09 6:13:14 AM Insteon ..Retry #1 required. Pausing 250ms for Hub to clear...
                  May-09 6:13:14 AM Insteon Received STX 0x50 (Raw Insteon Rec):42 3A 90 4B 77 93 2A 11 FF
                  May-09 6:13:14 AM Insteon ..Got NAK from the Hub for command
                  May-09 6:13:14 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
                  May-09 6:13:14 AM Insteon ..My XML buffer: 151515150250423A904B77932A11FF
                  May-09 6:13:10 AM Insteon Sending http://192.168.1.128:25105/3?0262423A900A11FF=I=3
                  May-09 6:13:10 AM Insteon Sending command 02 62 42 3A 90 0A 11 FF to Hub, (Expecting 0 bytes extra back) Pre-Payload ACK:False, NAK is ok:False
                  May-09 6:13:10 AM Insteon **Internal transmit attempt failed for CMD: 00 00 00 42 3A 90 0A 11 FF
                  May-09 6:13:10 AM Insteon ..Got NAK from the Hub for command
                  May-09 6:13:10 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
                  May-09 6:13:10 AM Insteon ..My XML buffer: 15151515
                  May-09 6:13:06 AM Insteon Sending http://192.168.1.128:25105/3?0262423A900A11FF=I=3
                  May-09 6:13:06 AM Insteon ..Retry #2 required. Pausing 300ms for Hub to clear...
                  May-09 6:13:06 AM Insteon ..Got NAK from the Hub for command
                  May-09 6:13:06 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
                  May-09 6:13:06 AM Insteon ..My XML buffer: 15151515
                  May-09 6:13:02 AM Insteon Sending http://192.168.1.128:25105/3?0262423A900A11FF=I=3
                  May-09 6:13:02 AM Insteon ..Retry #1 required. Pausing 250ms for Hub to clear...
                  May-09 6:13:02 AM Insteon ..Got NAK from the Hub for command
                  May-09 6:13:02 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
                  May-09 6:13:02 AM Insteon ..My XML buffer: 151515
                  May-09 6:13:01 AM Insteon Sending http://192.168.1.128:25105/3?0262423A900A11FF=I=3
                  May-09 6:13:01 AM Insteon Sending command 02 62 42 3A 90 0A 11 FF to Hub, (Expecting 0 bytes extra back) Pre-Payload ACK:False, NAK is ok:False
                  May-09 6:13:01 AM Insteon Did not receive a response from Kitchen Breakfast light (42.3A.90). Try #1 failed.
                  May-09 6:12:58 AM Insteon ..Got Hub Response 02 62 42 3A 90 0A 11 FF 06
                  May-09 6:12:58 AM Insteon Sending http://192.168.1.128:25105/1?XB=M=1
                  May-09 6:12:58 AM Insteon ..My XML buffer: 0262423A900A11FF06
                  May-09 6:12:56 AM Insteon Sending http://192.168.1.128:25105/3?0262423A900A11FF=I=3
                  May-09 6:12:56 AM Insteon Sending command 02 62 42 3A 90 0A 11 FF to Hub, (Expecting 0 bytes extra back) Pre-Payload ACK:False, NAK is ok:False
                  May-09 6:12:56 AM Insteon CAPIControl: Label=On, Value=100, ControlType=Button
                  May-09 6:12:56 AM Device Control Device: Kitchen Breakfast light to On (100) by/from: CAPI Control Handler

                  Comment


                    #10
                    My XML buffer: 151515
                    means the hub is busy, and won't accept new commands. so the plugin waits 250ms and retries.

                    the hub initially sent the command but didn't get an ACK from the light, so it tries again.

                    something is causing congestion in the hub; you shouldn't be seeing so many 151515 responses.

                    you need to look for noisy devices on the powerline or noisy RF devices.
                    Mark

                    HS3 Pro 4.2.19.5
                    Hardware: Insteon Serial PLM | AD2USB for Vista Alarm | HAI Omnistat2 | 1-Wire HA7E | RFXrec433 | Dahua Cameras | LiftMaster Internet Gateway | Tuya Smart Plugs
                    Plugins: Insteon (mine) | Vista Alarm (mine) | Omnistat 3 | Ultra1Wire3 | RFXCOM | HS MyQ | BLRadar | BLDenon | Tuya | Jon00 Charting | Jon00 Links
                    Platform: Windows Server 2022 Standard, i5-12600K/3.7GHz/10 core, 16GB RAM, 500GB SSD

                    Comment


                      #11
                      Problem solved

                      The problem was solved by moving the Hub to another location in the house. Therefore I conclude that it was communication noise related to other elements on that electrical circuit.

                      Since Insteon Hub and Light switch were only 6 feet apart I assumed reliable RF communication was guaranteed. However maybe partially garbled electric line communication can still cause retry issues as evident in the logs (Even with strong RF)?

                      Thanks,
                      aidesigner

                      Comment


                        #12
                        Originally posted by aidesigner View Post
                        The problem was solved by moving the Hub to another location in the house. Therefore I conclude that it was communication noise related to other elements on that electrical circuit.

                        Since Insteon Hub and Light switch were only 6 feet apart I assumed reliable RF communication was guaranteed. However maybe partially garbled electric line communication can still cause retry issues as evident in the logs (Even with strong RF)?

                        Thanks,
                        aidesigner
                        the hub receives message on the powerline and vai RF. so noise on either medium can cause problems.

                        I once had a switch go bad and it flooded the rf in the area and other rf only devices couldn't communicate with the interface.

                        i would suggest finding the noisy devices on the previous circuit and putting filterlincs on them to help avoid future issues.

                        glad you got this all working.
                        Mark

                        HS3 Pro 4.2.19.5
                        Hardware: Insteon Serial PLM | AD2USB for Vista Alarm | HAI Omnistat2 | 1-Wire HA7E | RFXrec433 | Dahua Cameras | LiftMaster Internet Gateway | Tuya Smart Plugs
                        Plugins: Insteon (mine) | Vista Alarm (mine) | Omnistat 3 | Ultra1Wire3 | RFXCOM | HS MyQ | BLRadar | BLDenon | Tuya | Jon00 Charting | Jon00 Links
                        Platform: Windows Server 2022 Standard, i5-12600K/3.7GHz/10 core, 16GB RAM, 500GB SSD

                        Comment


                          #13
                          With HubResponseTime=3 and GetXMLBufferInterval=2000 it still stopped working after a few days.

                          Here's the last couple minutes of the error log, plus the exception info and some of the configuration.

                          If more configuration would help, I'm happy to post it, just let me know.

                          If I'm reading the log correctly, it timed out while waiting for status from my patio lights. For what it's worth, I can turn that light on and off from HomeSeer's /deviceutility page and it works just fine. But maybe it just doesn't like to respond to status queries?

                          5/12/2018 10:28:43 PM - Starting Scheduled Polling...
                          5/12/2018 10:28:43 PM - Timed poll for Insteon device Outside Patio Lights (3D.0F.26), Last contact 5/12/2018 10:27:29 PM. Polling interval of 1 min. reached, polling...
                          5/12/2018 10:28:43 PM - Requesting Insteon status (Polling) for device Outside Patio Lights (3D.0F.26)
                          5/12/2018 10:28:43 PM - Attempting to update the status for Outside Patio Lights (3D.0F.26)
                          5/12/2018 10:28:43 PM - ResourceManager::RequestExclusive for Resource 1
                          5/12/2018 10:28:43 PM - ResourceManager::RequestExclusive acquired for Resource 1
                          5/12/2018 10:28:43 PM - Sending command 02 62 3D 0F 26 0A 19 00 to Hub, (Expecting 0 bytes extra back) Pre-Payload ACK:False, NAK is ok:False
                          5/12/2018 10:28:43 PM - Sending http://192.168.1.20:25105/3?02623D0F260A1900=I=3
                          5/12/2018 10:28:44 PM - ..My XML buffer begins with: 02623D0F260A19000602503D0F264B42ED2600FF
                          5/12/2018 10:28:44 PM - Sending http://192.168.1.20:25105/1?XB=M=1
                          5/12/2018 10:28:44 PM - Received STX 0x50 (Raw Insteon Rec):3D 0F 26 4B 42 ED 26 00 FF
                          5/12/2018 10:28:44 PM - PLMBuffer_Clean - Cleared 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 28 to locate next possible STX
                          5/12/2018 10:28:44 PM - ..Got Hub Response 02 62 3D 0F 26 0A 19 00 06
                          5/12/2018 10:28:44 PM - ResourceManager::ReleaseExclusive for Resource 1
                          5/12/2018 10:28:44 PM - CheckRawMessageMatch: 01 3D 0F 26 4B 42 ED 26 00 FF against key 0* 3D 0F 26 4B 42 ED 2* ** **
                          5/12/2018 10:28:44 PM - Wait: Found a matching Insteon raw message: 01 3D 0F 26 4B 42 ED 26 00 FF
                          5/12/2018 10:28:44 PM - Database recently heard delta value for device 3D.0F.26 is current.
                          5/12/2018 10:28:44 PM - Database delta value of 0 for device 3D.0F.26 is current. No changes since last database update.
                          5/12/2018 10:28:44 PM - StandardDeviceClass ProcessStatus called with Level:255
                          5/12/2018 10:28:44 PM - Received message from Outside Patio Lights (3D.0F.26) taking hops: 1
                          5/12/2018 10:28:44 PM - Received a Direct ACK from Outside Patio Lights (3D.0F.26): 3D 0F 26 4B 42 ED 26 00 FF
                          5/12/2018 10:28:44 PM - Setting status and value for device 3D.0F.26:1. Old status:100 Old Value:100, New Status:2 New Value:100
                          5/12/2018 10:28:45 PM - Timed poll for Insteon device Outside Generator Lights (3D.2D.C5), Last contact 5/12/2018 10:27:31 PM. Polling interval of 1 min. reached, polling...
                          5/12/2018 10:28:45 PM - Requesting Insteon status (Polling) for device Outside Generator Lights (3D.2D.C5)
                          5/12/2018 10:28:45 PM - Attempting to update the status for Outside Generator Lights (3D.2D.C5)
                          5/12/2018 10:28:45 PM - ResourceManager::RequestExclusive for Resource 1
                          5/12/2018 10:28:45 PM - ResourceManager::RequestExclusive acquired for Resource 1
                          5/12/2018 10:28:45 PM - Sending command 02 62 3D 2D C5 0A 19 00 to Hub, (Expecting 0 bytes extra back) Pre-Payload ACK:False, NAK is ok:False
                          5/12/2018 10:28:45 PM - Sending http://192.168.1.20:25105/3?02623D2DC50A1900=I=3
                          5/12/2018 10:28:46 PM - ..My XML buffer begins with: 02623D2DC50A19000602503D2DC54B42ED2600FF
                          5/12/2018 10:28:46 PM - Sending http://192.168.1.20:25105/1?XB=M=1
                          5/12/2018 10:28:46 PM - Received STX 0x50 (Raw Insteon Rec):3D 2D C5 4B 42 ED 26 00 FF
                          5/12/2018 10:28:46 PM - PLMBuffer_Clean - Cleared 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 28 to locate next possible STX
                          5/12/2018 10:28:46 PM - ..Got Hub Response 02 62 3D 2D C5 0A 19 00 06
                          5/12/2018 10:28:46 PM - ResourceManager::ReleaseExclusive for Resource 1
                          5/12/2018 10:28:46 PM - CheckRawMessageMatch: 01 3D 2D C5 4B 42 ED 26 00 FF against key 0* 3D 2D C5 4B 42 ED 2* ** **
                          5/12/2018 10:28:46 PM - Wait: Found a matching Insteon raw message: 01 3D 2D C5 4B 42 ED 26 00 FF
                          5/12/2018 10:28:46 PM - Database recently heard delta value for device 3D.2D.C5 is current.
                          5/12/2018 10:28:46 PM - Database delta value of 0 for device 3D.2D.C5 is current. No changes since last database update.
                          5/12/2018 10:28:46 PM - StandardDeviceClass ProcessStatus called with Level:255
                          5/12/2018 10:28:46 PM - Received message from Outside Generator Lights (3D.2D.C5) taking hops: 1
                          5/12/2018 10:28:46 PM - Received a Direct ACK from Outside Generator Lights (3D.2D.C5): 3D 2D C5 4B 42 ED 26 00 FF
                          5/12/2018 10:28:46 PM - Setting status and value for device 3D.2D.C5:1. Old status:100 Old Value:100, New Status:2 New Value:100
                          5/12/2018 10:28:47 PM - ..Finished Scheduled Polling for 2 devices.
                          5/12/2018 10:29:58 PM - Starting Scheduled Polling...
                          5/12/2018 10:29:58 PM - Timed poll for Insteon device Outside Patio Lights (3D.0F.26), Last contact 5/12/2018 10:28:44 PM. Polling interval of 1 min. reached, polling...
                          5/12/2018 10:29:58 PM - Requesting Insteon status (Polling) for device Outside Patio Lights (3D.0F.26)
                          5/12/2018 10:29:58 PM - Attempting to update the status for Outside Patio Lights (3D.0F.26)
                          5/12/2018 10:29:58 PM - ResourceManager::RequestExclusive for Resource 1
                          5/12/2018 10:29:58 PM - ResourceManager::RequestExclusive acquired for Resource 1
                          5/12/2018 10:29:58 PM - Sending command 02 62 3D 0F 26 0A 19 00 to Hub, (Expecting 0 bytes extra back) Pre-Payload ACK:False, NAK is ok:False
                          5/12/2018 10:29:58 PM - Sending http://192.168.1.20:25105/3?02623D0F260A1900=I=3
                          5/12/2018 10:29:59 PM - ..My XML buffer begins with: 02623D0F260A19000602503D0F264B42ED2A00FF
                          5/12/2018 10:29:59 PM - Sending http://192.168.1.20:25105/1?XB=M=1
                          5/12/2018 10:29:59 PM - Received STX 0x50 (Raw Insteon Rec):3D 0F 26 4B 42 ED 2A 00 FF
                          5/12/2018 10:29:59 PM - PLMBuffer_Clean - Cleared 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 28 to locate next possible STX
                          5/12/2018 10:29:59 PM - ..Got Hub Response 02 62 3D 0F 26 0A 19 00 06
                          5/12/2018 10:29:59 PM - ResourceManager::ReleaseExclusive for Resource 1
                          5/12/2018 10:29:59 PM - CheckRawMessageMatch: 01 3D 0F 26 4B 42 ED 2A 00 FF against key 0* 3D 0F 26 4B 42 ED 2* ** **
                          5/12/2018 10:29:59 PM - Wait: Found a matching Insteon raw message: 01 3D 0F 26 4B 42 ED 2A 00 FF
                          5/12/2018 10:29:59 PM - Database recently heard delta value for device 3D.0F.26 is current.
                          5/12/2018 10:29:59 PM - Database delta value of 0 for device 3D.0F.26 is current. No changes since last database update.
                          5/12/2018 10:29:59 PM - StandardDeviceClass ProcessStatus called with Level:255
                          5/12/2018 10:29:59 PM - Received message from Outside Patio Lights (3D.0F.26) taking hops: 1
                          5/12/2018 10:29:59 PM - Received a Direct ACK from Outside Patio Lights (3D.0F.26): 3D 0F 26 4B 42 ED 2A 00 FF
                          5/12/2018 10:29:59 PM - Setting status and value for device 3D.0F.26:1. Old status:100 Old Value:100, New Status:2 New Value:100
                          5/12/2018 10:30:01 PM - Timed poll for Insteon device Outside Generator Lights (3D.2D.C5), Last contact 5/12/2018 10:28:46 PM. Polling interval of 1 min. reached, polling...
                          5/12/2018 10:30:01 PM - Requesting Insteon status (Polling) for device Outside Generator Lights (3D.2D.C5)
                          5/12/2018 10:30:01 PM - Attempting to update the status for Outside Generator Lights (3D.2D.C5)
                          5/12/2018 10:30:01 PM - ResourceManager::RequestExclusive for Resource 1
                          5/12/2018 10:30:01 PM - ResourceManager::RequestExclusive acquired for Resource 1
                          5/12/2018 10:30:01 PM - Sending command 02 62 3D 2D C5 0A 19 00 to Hub, (Expecting 0 bytes extra back) Pre-Payload ACK:False, NAK is ok:False
                          5/12/2018 10:30:01 PM - Sending http://192.168.1.20:25105/3?02623D2DC50A1900=I=3
                          5/12/2018 10:30:01 PM - ..My XML buffer begins with: 02623D2DC50A19000602503D2DC54B42ED2600FF
                          5/12/2018 10:30:01 PM - Sending http://192.168.1.20:25105/1?XB=M=1
                          5/12/2018 10:30:01 PM - Received STX 0x50 (Raw Insteon Rec):3D 2D C5 4B 42 ED 26 00 FF
                          5/12/2018 10:30:01 PM - PLMBuffer_Clean - Cleared 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 28 to locate next possible STX
                          5/12/2018 10:30:01 PM - ..Got Hub Response 02 62 3D 2D C5 0A 19 00 06
                          5/12/2018 10:30:01 PM - ResourceManager::ReleaseExclusive for Resource 1
                          5/12/2018 10:30:01 PM - CheckRawMessageMatch: 01 3D 2D C5 4B 42 ED 26 00 FF against key 0* 3D 2D C5 4B 42 ED 2* ** **
                          5/12/2018 10:30:01 PM - Wait: Found a matching Insteon raw message: 01 3D 2D C5 4B 42 ED 26 00 FF
                          5/12/2018 10:30:01 PM - Database recently heard delta value for device 3D.2D.C5 is current.
                          5/12/2018 10:30:01 PM - Database delta value of 0 for device 3D.2D.C5 is current. No changes since last database update.
                          5/12/2018 10:30:01 PM - StandardDeviceClass ProcessStatus called with Level:255
                          5/12/2018 10:30:01 PM - Received message from Outside Generator Lights (3D.2D.C5) taking hops: 1
                          5/12/2018 10:30:01 PM - Received a Direct ACK from Outside Generator Lights (3D.2D.C5): 3D 2D C5 4B 42 ED 26 00 FF
                          5/12/2018 10:30:01 PM - Setting status and value for device 3D.2D.C5:1. Old status:100 Old Value:100, New Status:2 New Value:100
                          5/12/2018 10:30:02 PM - ..Finished Scheduled Polling for 2 devices.
                          5/12/2018 10:31:13 PM - Starting Scheduled Polling...
                          5/12/2018 10:31:13 PM - Timed poll for Insteon device Outside Patio Lights (3D.0F.26), Last contact 5/12/2018 10:29:59 PM. Polling interval of 1 min. reached, polling...
                          5/12/2018 10:31:13 PM - Requesting Insteon status (Polling) for device Outside Patio Lights (3D.0F.26)
                          5/12/2018 10:31:13 PM - Attempting to update the status for Outside Patio Lights (3D.0F.26)
                          5/12/2018 10:31:13 PM - ResourceManager::RequestExclusive for Resource 1
                          5/12/2018 10:31:13 PM - ResourceManager::RequestExclusive acquired for Resource 1
                          5/12/2018 10:31:13 PM - Sending command 02 62 3D 0F 26 0A 19 00 to Hub, (Expecting 0 bytes extra back) Pre-Payload ACK:False, NAK is ok:False
                          5/12/2018 10:31:13 PM - Sending http://192.168.1.20:25105/3?02623D0F260A1900=I=3
                          5/12/2018 10:31:16 PM - ..did not receive a response from the Hub
                          5/12/2018 10:31:16 PM - ..Retry #1 required. Pausing 250ms for Hub to clear...
                          5/12/2018 10:31:17 PM - Sending http://192.168.1.20:25105/3?02623D0F260A1900=I=3
                          5/12/2018 10:31:20 PM - ..did not receive a response from the Hub
                          5/12/2018 10:31:20 PM - ..Retry #2 required. Pausing 300ms for Hub to clear...
                          5/12/2018 10:31:20 PM - Sending http://192.168.1.20:25105/3?02623D0F260A1900=I=3
                          5/12/2018 10:31:21 PM - ***:Error in Hub.GetBuffer: The request was aborted: The operation has timed out. -- Details System.Net.WebException: The request was aborted: The operation has timed out.
                          at System.Net.HttpWebRequest.GetResponse()
                          at System.Xml.XmlDownloadManager.GetNonFileStream(Uri uri, ICredentials credentials, IWebProxy proxy, RequestCachePolicy cachePolicy)
                          at System.Xml.XmlDownloadManager.GetStream(Uri uri, ICredentials credentials, IWebProxy proxy, RequestCachePolicy cachePolicy)
                          at System.Xml.XmlUrlResolver.GetEntity(Uri absoluteUri, String role, Type ofObjectToReturn)
                          at System.Xml.XmlTextReaderImpl.FinishInitUriString()
                          at System.Xml.XmlTextReaderImpl..ctor(String uriStr, XmlReaderSettings settings, XmlParserContext context, XmlResolver uriResolver)
                          at System.Xml.XmlReaderSettings.CreateReader(String inputUri, XmlParserContext inputContext)
                          at System.Xml.XmlReader.Create(String inputUri, XmlReaderSettings settings, XmlParserContext inputContext)
                          at Insteon.Support.Hub.SocketPortClass.GetBuffer()
                          --------*End Pre-Error Log*--------------
                          --------*Start C:\Program Files (x86)\HomeSeer HS3\Config\Insteon.ini*--------------
                          [Hub]
                          ResponseTime=3
                          GetXMLBufferInterval=2000
                          [Config]
                          MaxHops=2
                          NumRetries=5
                          WaitTimeout=3
                          DetailedLog=1
                          UseLocation2=0
                          DoCleanups=1
                          DisablePolling=0
                          SortDeviceLinks=0
                          InterfacePort=192.168.1.20:25105
                          X10Enabled=0
                          InterfaceCapability=5

                          Comment


                            #14
                            Originally posted by NateW View Post
                            With HubResponseTime=3 and GetXMLBufferInterval=2000 it still stopped working after a few days.

                            Here's the last couple minutes of the error log, plus the exception info and some of the configuration.

                            If more configuration would help, I'm happy to post it, just let me know.

                            If I'm reading the log correctly, it timed out while waiting for status from my patio lights. For what it's worth, I can turn that light on and off from HomeSeer's /deviceutility page and it works just fine. But maybe it just doesn't like to respond to status queries?
                            Nate,
                            the error is generated because the hub isn't responding to the command, not because your light isn't responding.

                            can you describe the network connections between your hs server and the hub? are they both connected to the same switch, or something more complex?
                            Mark

                            HS3 Pro 4.2.19.5
                            Hardware: Insteon Serial PLM | AD2USB for Vista Alarm | HAI Omnistat2 | 1-Wire HA7E | RFXrec433 | Dahua Cameras | LiftMaster Internet Gateway | Tuya Smart Plugs
                            Plugins: Insteon (mine) | Vista Alarm (mine) | Omnistat 3 | Ultra1Wire3 | RFXCOM | HS MyQ | BLRadar | BLDenon | Tuya | Jon00 Charting | Jon00 Links
                            Platform: Windows Server 2022 Standard, i5-12600K/3.7GHz/10 core, 16GB RAM, 500GB SSD

                            Comment


                              #15
                              Homeseer is using a 2234-222 hub, both using wired ethernet. But, there are three switches in between them. The Homeseer PC is connected to a switch, the Hub is connected to another switch, and there's a third in between those two. I will try plugging the hub into the same switch as the Homeseer PC, we'll see if that helps.

                              Two things to note, though...

                              Both the Hub and the PC that I'm using to type this are on the same switch, and I use remote desktop to administer the Homeseer PC from here all the time, and remote desktop works just fine.

                              Again, why not just catch the exception and keep running? I mean, as opposed to catching the exception and halting the plugin until the user manually restarts it. I get that you're catching it and logging it, but that should cause the current operation to fail (no status for the dimmer), it shouldn't plug the plugin into a state where everything fails until the user intervenes.

                              very time that happens, random stuff stops working around my house. Every time that happens, I just restart the plugin. Every time that happens, all is well for a few more days.

                              If I had a choice between an out-of-sync device in Homeseer once every few days, versus completely nonfunctional Insteon every few days... obviously I'd rather have everything else keep working while I investigate the timeout problem.

                              Network timeouts are just a fact of life. It's OK to have interactive software throw up an error when they happen, but something that runs as a service should just log the error and continue functioning as best it can. Halting isn't reasonable, especially since experience has shown that if I restart the plugin everything will work again, for days.

                              Comment

                              Working...
                              X