Insteon IO Linc Garage Door Contact - Slow Update

Hawk37 · November 27, 2022, 3:30pm

Slow Garage Door Contact

I don’t believe I ever got the garage door status working correctly since I set up my Insteon Binding. I decided to look into it this weekend and found (while using Insteon-Terminal) that the hub had a responder for the IOLinc, but that the IOLinc wasn’t set as a controller for the hub. I added the controller to the IOLinc database and was pleasantly surprised that I started seeing the contact status change.

After playing around with things for a little bit, I’ve noticed that the message from the contact comes in immediately when monitoring the insteon binding from the openhab console, but that the eventlog/status take some variable duration afterwards to update. Here’s what I’m seeing in the logs:

Manually Opening Garage Door

Console Monitoring:
2022-11-27 08:51:26.229 IN:Cmd:0x50|fromAddress:45.31.0C|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|command2:0x00|
2022-11-27 08:51:26.247 IN:Cmd:0x50|fromAddress:45.31.0C|toAddress:31.34.98|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x13|command2:0x01|
2022-11-27 08:51:26.255 IN:Cmd:0x50|fromAddress:45.31.0C|toAddress:13.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|
Openhab Event Log:
2022-11-27 08:51:47.343 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'garageDoorContact' changed from CLOSED to OPEN

Manually Closing Garage Door:
2022-11-27 08:51:47.334 IN:Cmd:0x50|fromAddress:45.31.0C|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x00|
2022-11-27 08:51:47.352 IN:Cmd:0x50|fromAddress:45.31.0C|toAddress:31.34.98|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x01|
2022-11-27 08:51:47.365 IN:Cmd:0x50|fromAddress:45.31.0C|toAddress:11.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|
Openhab Event Log:
2022-11-27 08:54:09.995 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'garageDoorContact' changed from OPEN to CLOSED

As you can see, the open status took 21 seconds to update after the the contact send the 0x13, and the the close status wasn’t until 2m and 22s later. Any ideas on what’s causing this delay?

Platform information:

Hardware: Pi3B - ARM Cortex-A53 1.2GHz/1GB Ram/32GB SD
OS: OpenHabian 3.3 (Raspian GNU/Linux 11)
Java Runtime Environment: Zulu 11 Open JDK 32-bit
openHAB version: 3.3.0

ranielsen · November 27, 2022, 5:14pm

That’s weird, what do you see for that device when you run the openhab:insteon display_local_database console command?

Hawk37 · November 27, 2022, 5:55pm

It lists:
45.31.0C: hub controls groups (0,8) and responds to groups (1)

Hawk37 · November 27, 2022, 6:36pm

I was starting to think the random time updates might have just been the binding’s typical 5min polling interval noticing the status change. However, I’ve gotten updates much closer than 5min to each other. I just got some state changes 7 seconds apart from each other:

2022-11-27 12:09:03.229 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'garageDoorContact' changed from CLOSED to OPEN
2022-11-27 12:09:10.258 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'garageDoorContact' changed from OPEN to CLOSED

Granted, the first state change was 2 minutes after the actual event (opening). The second was within a few seconds of closing.

ranielsen · November 27, 2022, 8:30pm

What groups are configured for you IO Linc.Make sure they match.

Hawk37 · November 28, 2022, 2:30pm

I know you can configure the group for the key pad in the binding, but I’m not seeing that for the IOlinc. So, I’m guessing you mean in the insteon DB itself?

Here’s the IOlinc DB:

0fff hub                            31.34.98  RESP  10100010 group: 00 ON LVL:   0 RMPRT:   0 BUTTON:   0
0ff7 hub                            31.34.98  RESP  10100010 group: 08 ON LVL:   0 RMPRT:   0 BUTTON:   0
0fef hub                            31.34.98  CTRL  11100010 group: 01 ON LVL:   3 RMPRT:  28 BUTTON:   1
0fe7 00.00.00                       00.00.00 (STOP) 00000000 group: 00 ON LVL:   0 RMPRT:   0 BUTTON:   0

To get things to the state they’re in now I had to the the CTRL entry with insteon-terminal, it wasn’t there originally.

And the relevant entries in the hub DB:

0000 GarageDoor                     45.31.0C  RESP  10100010 group: 01 data: 00 00 00
0000 GarageDoor                     45.31.0C  CTRL  11101010 group: 00 data: 07 00 41
0000 GarageDoor                     45.31.0C  CTRL  11101010 group: 08 data: 07 00 41

Surprisingly, the group 01 responder was already there when I was investigating. Looking it over again, I did try to add Button 1 to the controller on the IOlinc like a keypad. The IOLinc isn’t fully implemented on insteon-terminal. I did some guessing there. Not sure if that button 1 in the data matters. I see the group 00 and group 08 both have button 41 on the hub and 0 on the IOLinc. Anyone have a working IOlinc they could check the DB entries on to compare?

ranielsen · November 28, 2022, 3:57pm

One thing that seems odd is that you have hub controlling two groups (00 and 08)

Hawk37 · November 28, 2022, 11:09pm

I’ve got no reference to compare against. This is my only IOlinc and I set it up originally with the insteon app. I haven’t figured out all of the uses for groups on the insteon network, but it doesn’t sound two odd based on what’s in the binding documentation:

Many Insteon devices send out messages on different group numbers, depending on what happens to them. A leak sensor may send out a message on group #1 when dry, and on group #2 when wet. The default group used for e.g. linking two light switches is usually group #1.

I’ll see if I can use the terminal to see what the two groups are doing. Not sure what I would change them too.

Either way it does seem like OH is picking up the change and more often than the 5 minute poll interval. Not sure what’s causing it to be slow. It does seem like it recognizes subsequent status changes in a much more timely manner. Often when I open the door it takes a couple minutes to see that the door is open, but sees the open then switches to closed again pretty immediately when the door is closed. Its almost like something isn’t quite getting cleaned up or acknowledged, but the next trigger goes out and gets things going. I took the magnet off the door and triggered it by hand a few times and saw it change pretty rapidly in the event log. Not sure what else to look into. Any suggestions would be appreciated!

ranielsen · November 29, 2022, 1:16pm

You only need one not two, you can remove one of them.

Do you have both a switch and contact configured? Can you share the relevant item configuration and what shows up in the events.log file?

Hawk37 · November 29, 2022, 3:49pm

You only need one not two, you can remove one of them.

I agree it should only need one group, but I don’t have enough info to warrant removing one. Do you have an IOlinc set up and and working with one responder group? If so, could you share its DB for comparison? Wondering what groups and data it has configured.

I’m of the opinion “if it ain’t broke, don’t fix it” in this case. I think those two groups are related to the switch not the contact. If you recall from my initial post I had to add the controller to the IOlinc (group 1) to get the contact to start updating in OH. I don’t see the IOlinc having an extra responder group being a part of the issue.

Do you have both a switch and contact configured?

Yes, I have both the switch and contact configured. The switch has been working flawlessly. Its the contact that I’ve been looking into. I didn’t really use it in OH2 (can’t remember if it was working), and never bothered to troubleshoot in OH3 until now. Below is the thing config:

UID: insteon:device:65d7380c6b:2a4ad8f6f9
label: GarageIOLink
thingTypeUID: insteon:device
configuration:
  productKey: "0x00001A"
  address: 45.31.0C
bridgeUID: insteon:network:65d7380c6b
location: Garage

I configured/imported all of my things into the UI when I upgraded from OH2 to OH3. I had it set up as follows in OH2 items file:

Switch   garageDoorOpener     "Garage door opener"                         <garagedoor>  ["Switchable"]  {insteonplm="45.31.0C:0x00001A#switch", autoupdate="false"}
Contact  garageDoorContact    "Garage door contact [MAP(contact.map):%s]"                                {insteonplm="45.31.0C:0x00001A#contact"}

With the associated sitemap, (still used in OH3):

sitemap garageDoorOpener label="GarageDoor"

 {  Switch item=garageDoorOpener label="garage door opener" mappings=[ ON="OPEN/CLOSE"]
    Text item=garageDoorContact   }

Its now in the UI as follows (thing, with items linked to the switch and contact channels):

As for the events.log, I believe I’ve already shared the relevant entries in posts above, comparing them to the console output. There’s no other entries in the event log currently for the garagedoor contact. Here’s an example from today, trigger the garage door from the switch:

2022-11-29 09:40:50.809 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'garageDoorOpener' received command ON
2022-11-29 09:40:50.830 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'garageDoorOpener' predicted to become ON
2022-11-29 09:40:50.846 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'garageDoorOpener' changed from OFF to ON
2022-11-29 09:40:54.033 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'garageDoorOpener' changed from ON to OFF
2022-11-29 09:41:55.926 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'garageDoorOpener' received command ON
2022-11-29 09:41:55.935 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'garageDoorOpener' predicted to become ON
2022-11-29 09:41:55.943 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'garageDoorOpener' changed from OFF to ON
2022-11-29 09:41:59.403 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'garageDoorOpener' changed from ON to OFF
2022-11-29 09:42:08.456 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'garageDoorContact' changed from CLOSED to OPEN
2022-11-29 09:42:40.621 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'garageDoorContact' changed from OPEN to CLOSED

The Contact Events didn’t occur until the door was closed again. The Closed to Open transition seemed to occur when the door closed again (~13s after it was commanded to close). The Open to Closed transition occurs 32 seconds later. This delayed behavior is what I’m trying to correct.

ranielsen · November 29, 2022, 7:49pm

Everything looks correct to me. Maybe you’ll need to enable debug logging and see what it shows.

Hawk37 · December 1, 2022, 4:22am

Ok, did some more troubleshooting with: “openhab> log:set trace org.openhab.bindg.insteon” to get more info. What I’ve found is that Open and Close immediate events are actually reversed, but that when the 300s query checks the contact, it is correcting things.

I noticed there was not status update when I opened the door. Then found the Open status update when the door closed that I had noted before in the typical console log. I eventually found the following query after some waiting with the door closed:

2022-11-30 21:13:32.135 [DEBUG] [ding.insteon.internal.InsteonBinding] - got msg: IN:Cmd:0x50|fromAddress:45.31.0C|toAddress:31.34.98|messageFlags:0x21=ACK_OF_DIRECT:1:0|command1:0x02|command2:0x01|
2022-11-30 21:13:32.137 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: IOLincContact
2022-11-30 21:13:32.139 [DEBUG] [on.internal.device.MessageDispatcher] - 45.31.0C:IOLincContact DIRECT_ACK: q:QUERY_PENDING cmd: 80
2022-11-30 21:13:32.141 [DEBUG] [on.internal.device.MessageDispatcher] - changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:45.31.0C|toAddress:31.34.98|messageFlags:0x21=ACK_OF_DIRECT:1:0|command1:0x02|command2:0x01|
2022-11-30 21:13:32.142 [DEBUG] [steon.internal.device.MessageHandler] - ContactRequestReplyHandler: set contact 45.31.0C to: CLOSED
2022-11-30 21:13:32.144 [DEBUG] [nsteon.internal.device.DeviceFeature] - 45.31.0C:IOLincContact publishing: CLOSED
2022-11-30 21:13:32.146 [TRACE] [nternal.device.DeviceFeatureListener] - old state: OpenClosedType:OPEN=?CLOSED
2022-11-30 21:13:32.148 [TRACE] [nsteon.internal.device.DeviceFeature] - IOLincContact set query status to: QUERY_ANSWERED
2022-11-30 21:13:32.152 [DEBUG] [on.internal.device.MessageDispatcher] - defdisp: 45.31.0C:IOLincContact set status to: QUERY_ANSWERED
2022-11-30 21:13:32.154 [TRACE] [nsteon.internal.device.InsteonDevice] - handled reply of direct: IOLincContact(1:1:4)

I’d read this similar post a few times. Bernd explains the query command 2 is the returned state of the contact. It also gave me the idea that the on an off might be switched.

This site has some good info on commands. 0x11 is ON, and 0x13 is OFF on the group command “toAddress:00.00.01”.

It seems that, as Bernd put it, Command2 = 0x01 = CLOSED, and Command2 = 0x00 = OPEN for the query. Conversely the binding is interpreting as 0x11 = ON = OPEN, and 0x13 = OFF = CLOSED when the group message is received.

It now seems obvious, looking back at my first post, that the event is backwards. The Closed to Open transition occurred 10ms after the 0x11 message at the start of manually closing the garage door.

So, the sequence is not delayed. It is actually incorrect. The door is closed initially, thanks to the query getting it right. However, when it first opens, the triggered event status is also closed, and therefore not reported. When the door closes again, an Open Status is immediately triggered. In reality the door just closed. Eventually, the query runs again and sets the status correctly back to closed.

This explains why I was seeing immediate updates outside of the query. The kicker is that the query is correctly reading the status. Thus giving it the appearance of being correct.

It looks like the device itself can send different updates depending on what state the sensor is in when it is initially linked to the hub. So… I unlinked and re-linked the IOlinc the low-tech way of pressing the button and holding. When I linked the IOlinc to the hub again the door was open. Now the contact switches immediately with the sensor!

The note below (from the binding documentation) mentions the “polling” being off when in reality it looks like its the status change event not the polling/query:

NOTE: If the I/O Linc returns the wrong value when the device is polled (For example you open the garage door and the state correctly shows OPEN, but during polling it shows CLOSED), you probably linked the device with the PLM or hub when the door was in the wrong position. You need unlink and then link again with the door in the opposite position. Please see the Insteon I/O Linc documentation for further details.

This didn’t point me in the right direction as polling/queries were returning correctly. The instructions from Insteon it recommends you refer to also show linking the device with the sensor input on (contacts together), which deos not work for the binding.

From what I can tell, the status from the query is true to the sensor input: 01 = ON = CLOSED & 00 = OFF = OPEN, whereas the messages the binding expects are 0x11 = ON = OPEN & 0x13 = OFF = CLOSED. I see a case for not updating now, to avoid messing up current users, but probably a good idea to document that the input needs to be OFF when the IO Linc is linked to the hub for the binding to work correctly.

TLDR; The contact wasn’t slow, the status events were actually inverted and eventually getting corrected by the query in 5 minute intervals. The IO Linc device can be configured to send matching or inverted messages based on the sensor input. This is determined by the state of the sensor when the IOLinc is linked to the responder (the hub in my case). Linking the IOlinc to the hub again with the garage door open (contacts apart for me) solved the issue.

Hawk37 · December 1, 2022, 6:14am

I tried making a pull request to update the documentation at least. First time making a PR, apologies if I missed a step.