IOLinc Status Not Updating

[tloomos]

Hi, I have 2 IOLinc modules I use to control my garage doors. The status of the sensor is not reliably updating within Homeseer. The status in the ISY is correct, but it's not always being refreshed into Homeseer when it changes. Not sure what I can check to help troubleshoot this?

I'm running HS4 v4.1.16.0 and ISYInsteon version 3.0.1.19

[bpwwer]

You can increase the logging to status or notice and watch the log when IOLinc status is being changed. That should let you know if the plug-in is receiving those status updates. Switching to debug log level should show the actual messages being received from the ISY, but there may be a lot of messages in the log to look through.

[tloomos]

I've turned up the logging and captured the results after opening and closing one of the doors a few times. I don't see any changes to the sensor being logged.

I have the controller setup per instructions for setting up an IOLinc to control a garage door with KPL buttons to control/respond. So my setup includes 2 scenes, one called "Teds Garage Door" (HS ID=1138) to control the relay and open/close the door and one called "Teds Garage Indicator" to show the state of the sensor and control lighting up the KPL buttons. When I trigger the garage door, everything in the ISY shows the expected values, so the sensor device and indicator scene show "Off" when the door is closed and "On" when it is open. However, the corresponding devices in HS are not reflecting the updates.

Here's the contents of the log after triggering open and close a couple times...

6/30/2021 9:03:48 PM Legacy-Plugin ISYInsteon TriggerChange : Event Name = Delayed Actions Driveway Motion (Delayed Action) - 2
6/30/2021 9:03:48 PM Legacy-Plugin ISYInsteon TriggerChange : Event - CONFIG_CHANGE: Event Added Event Ref# = 2367 dac = 1
6/30/2021 9:03:48 PM Legacy-Plugin ISYInsteon TriggerChange : Event Name = Delayed Actions Driveway Motion (Delayed Action) - 2
6/30/2021 9:03:48 PM Legacy-Plugin ISYInsteon TriggerChange : Event - CONFIG_CHANGE: Event Action Added Event Ref# = 2367 dac = 3
6/30/2021 9:03:48 PM Legacy-Plugin ISYInsteon TriggerChange : Event Name = Delayed Actions Driveway Motion (Delayed Action) - 2
6/30/2021 9:03:48 PM Legacy-Plugin ISYInsteon TriggerChange : Event - CONFIG_CHANGE: Event Trigger Added Event Ref# = 2367 dac = 3
6/30/2021 9:03:42 PM Legacy-Plugin ISYInsteon Command Queue is now empty.
6/30/2021 9:03:42 PM Legacy-Plugin ISYInsteon QueueLoop : Command for Outside/Garage 2/Teds Garage Door finished and removed from queue. Queue size = 1
6/30/2021 9:03:42 PM Legacy-Plugin ISYInsteon SendRequest : Sending command [DON258244
]
6/30/2021 9:03:42 PM Legacy-Plugin ISYInsteon Authorize : Authorize: encoding = "xxxxxxxxxxxxxxxxxxx" to "xxxxxxxxxxxxxxxxxxxxxxxxxxxx"
6/30/2021 9:03:42 PM Legacy-Plugin ISYInsteon ProcessCommand : Sending DON, to Outside/Garage 2/Teds Garage Door Attempt 0
6/30/2021 9:03:42 PM Legacy-Plugin ISYInsteon QueueLoop : Processing Command for Outside/Garage 2/Teds Garage Door. Queue size = 1
6/30/2021 9:03:42 PM Legacy-Plugin ISYInsteon Control : Exit control function
6/30/2021 9:03:42 PM Legacy-Plugin ISYInsteon Add : Command for Outside/Garage 2/Teds Garage Door added to queue. Queue size = 1
6/30/2021 9:03:42 PM Legacy-Plugin ISYInsteon SetIOMulti : SetIOMulti set 1138 to value 100
6/30/2021 9:03:42 PM HomeSeer Device Control Device: Outside Garage 2 Teds Garage Door to On (100) by/from: CAPI Control Handler
6/30/2021 9:03:27 PM Legacy-Plugin ISYInsteon Event Queue is now empty.
6/30/2021 9:03:27 PM Legacy-Plugin ISYInsteon QueueLoop : Event removed from queue. Queue size = 0
6/30/2021 9:03:27 PM Legacy-Plugin ISYInsteon TriggerEventHandler : TRIGGER: Searching full trigger list for match.
6/30/2021 9:03:27 PM Legacy-Plugin ISYInsteon TriggerEventHandler : Reason [Communication Error] Trigger [ISY_COMM_ERROR] Data [] instance []
6/30/2021 9:03:27 PM Legacy-Plugin ISYInsteon TriggerEventHandler : TRIGGER: ISY Error Trigger Communication Error
6/30/2021 9:03:27 PM Legacy-Plugin ISYInsteon RaiseTriggers : ----> Watchdog timeout.
6/30/2021 9:03:27 PM Legacy-Plugin ISYInsteon watchdog timeout occured.
6/30/2021 9:03:27 PM Legacy-Plugin ISYInsteon Add : Event added to queue. Queue size = 1
6/30/2021 9:02:40 PM Legacy-Plugin ISYInsteon Command Queue is now empty.
6/30/2021 9:02:40 PM Legacy-Plugin ISYInsteon QueueLoop : Command for Outside/Garage 2/Teds Garage Door finished and removed from queue. Queue size = 1
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon SendRequest : Sending command [DON258244
]
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon Authorize : Authorize: encoding = "xxxxxxxxxxxxxxxxxxxx" to "xxxxxxxxxxxxxxxxxxxxxxxxxxxxx"
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon ProcessCommand : Sending DON, to Outside/Garage 2/Teds Garage Door Attempt 0
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon Control : Exit control function
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon QueueLoop : Processing Command for Outside/Garage 2/Teds Garage Door. Queue size = 1
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon Add : Command for Outside/Garage 2/Teds Garage Door added to queue. Queue size = 1
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon SetIOMulti : SetIOMulti set 1138 to value 100
6/30/2021 9:02:39 PM HomeSeer Device Control Device: Outside Garage 2 Teds Garage Door to On (100) by/from: CAPI Control Handler
6/30/2021 9:02:40 PM Legacy-Plugin ISYInsteon Command Queue is now empty.
6/30/2021 9:02:40 PM Legacy-Plugin ISYInsteon QueueLoop : Command for Outside/Garage 2/Teds Garage Door finished and removed from queue. Queue size = 1
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon SendRequest : Sending command [DON258244
]
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon Authorize : Authorize: encoding = "xxxxxxxxxxxxxxx" to "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon ProcessCommand : Sending DON, to Outside/Garage 2/Teds Garage Door Attempt 0
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon Control : Exit control function
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon QueueLoop : Processing Command for Outside/Garage 2/Teds Garage Door. Queue size = 1
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon Add : Command for Outside/Garage 2/Teds Garage Door added to queue. Queue size = 1
6/30/2021 9:02:39 PM Legacy-Plugin ISYInsteon SetIOMulti : SetIOMulti set 1138 to value 100
6/30/2021 9:02:39 PM HomeSeer Device Control Device: Outside Garage 2 Teds Garage Door to On (100) by/from: CAPI Control Handler
6/30/2021 9:00:07 PM Legacy-Plugin ISYInsteon TriggerChange : Event Name = Delayed Actions Driveway Motion (Delayed Action) - 1
6/30/2021 9:00:07 PM Legacy-Plugin ISYInsteon TriggerChange : Event - CONFIG_CHANGE: Event Added Event Ref# = 2366 dac = 1
6/30/2021 9:00:07 PM Legacy-Plugin ISYInsteon TriggerChange : Event Name = Delayed Actions Driveway Motion (Delayed Action) - 1
6/30/2021 9:00:07 PM Legacy-Plugin ISYInsteon TriggerChange : Event - CONFIG_CHANGE: Event Action Added Event Ref# = 2366 dac = 3
6/30/2021 9:00:07 PM Legacy-Plugin ISYInsteon TriggerChange : Event Name = Delayed Actions Driveway Motion (Delayed Action) - 1
6/30/2021 9:00:07 PM Legacy-Plugin ISYInsteon TriggerChange : Event - CONFIG_CHANGE: Event Trigger Added Event Ref# = 2366 dac = 3
6/30/2021 9:00:07 PM HomeSeer Device Control Device: Virtual - Blue Iris Motion Front Yard Driveway Motion to On (1)
6/30/2021 9:00:07 PM HomeSeer Event Event Trigger "Blue Iris Motion Triggers Driveway Motion Trigger"
6/30/2021 9:00:00 PM Legacy-Plugin ISYInsteon Command Queue is now empty.
6/30/2021 9:00:00 PM Legacy-Plugin ISYInsteon QueueLoop : Command for Outside/Garage 2/Teds Garage Door finished and removed from queue. Queue size = 1
6/30/2021 9:00:00 PM Legacy-Plugin ISYInsteon SendRequest : Sending command [DON258244
]
6/30/2021 9:00:00 PM Legacy-Plugin ISYInsteon Authorize : Authorize: encoding = "xxxxxxxxxxxxxxxx" to "xxxxxxxxxxxxxxxxxxxxxxxxxxxxx"
6/30/2021 9:00:00 PM Legacy-Plugin ISYInsteon ProcessCommand : Sending DON, to Outside/Garage 2/Teds Garage Door Attempt 0
6/30/2021 9:00:00 PM Legacy-Plugin ISYInsteon QueueLoop : Processing Command for Outside/Garage 2/Teds Garage Door. Queue size = 1
6/30/2021 9:00:00 PM Legacy-Plugin ISYInsteon Control : Exit control function
6/30/2021 9:00:00 PM Legacy-Plugin ISYInsteon Add : Command for Outside/Garage 2/Teds Garage Door added to queue. Queue size = 1
6/30/2021 9:00:00 PM Legacy-Plugin ISYInsteon SetIOMulti : SetIOMulti set 1138 to value 100
6/30/2021 9:00:00 PM HomeSeer Device Control Device: Outside Garage 2 Teds Garage Door to On (100) by/from: CAPI Control Handler

[bpwwer]

Are you seeing a lot of these?

[6/30/2021 9:03:27 PM Legacy-Plugin ISYInsteon RaiseTriggers : ----> Watchdog timeout.
6/30/2021 9:03:27 PM Legacy-Plugin ISYInsteon watchdog timeout occured.
6/30/2021 9:03:27 PM Legacy-Plugin ISYInsteon Add : Event added to queue. Queue size = 1

This is an internal event indicating that the plug-in has not seen anything from the ISY is quite a while. The plug-in uses a separate thread to monitor the messages that the ISY sends. It looks like something is either blocking those messages (firewall/AV) or something has gone wrong with the connection. If the connection fails, you should be seeing error messages for that. The ISY only allows a fixed number of those types of connections so possibly it rejected that connection attempt.

You should be seeing messages like this (I'm set to STATUS log level). I turned a light on and then off. The two highlighted messages are based on the response that the ISY sends back. I don't see those types of messages in your log.

[COLOR=#c0392b]Jul-01 9:37:56 AM ISYInsteon Crafty Room/Craft:Ceiling Cans now set to 0[/COLOR]
Jul-01 9:37:56 AM ISYInsteon ISY is idle.
Jul-01 9:37:56 AM ISYInsteon ISY is busy.
Jul-01 9:37:56 AM ISYInsteon Sending command [DOF017 D 96 10 ]
Jul-01 9:37:56 AM Device Control Device: Crafty Room Craft:Ceiling Cans to Off (0) by/from: CAPI Control Handler
Jul-01 9:37:56 AM ISYInsteon Sending command [ ]
[COLOR=#c0392b]Jul-01 9:37:54 AM ISYInsteon Crafty Room/Craft:Ceiling Cans now set to 255[/COLOR]
Jul-01 9:37:53 AM ISYInsteon ISY is idle.
Jul-01 9:37:53 AM ISYInsteon ISY is busy.
Jul-01 9:37:53 AM ISYInsteon Sending command [DON25517 D 96 10 ]
Jul-01 9:37:53 AM Device Control Device: Crafty Room Craft:Ceiling Cans to On (100) by/from: CAPI Control Handler

When you re-start the plug-in with the log level set to STATUS or higher, you should see it updating the status for all of the devices, The first thing the ISY does when the monitoring connection is made is to send the current status of all devices. For example, I see

Jul-01 9:44:19 AM ISYInsteon Crafty Room/Craft:Ceiling Cans now set to 0
Jul-01 9:44:19 AM ISYInsteon Crafty Room/Craft:Ceiling Cans on level at 255

For the same light as above. If you don't see these types of status messages when restarting, you should be seeing some type of error to indicate what has failed. If you aren't seeing an error, I'd really suspect that a firewall or AV software is blocking the messages from the ISY.

[tloomos]

THANK YOU! I wouldn't have thought to check that. I turned off AV on my Homeseer server and restarted the ISYInsteon plugin and I'm now seeing the status getting updated properly.