Insteon IOLinc polling returns wrong status?

Add-ons Bindings
1

Hello,

I have an IOLinc hooked up to my garage door, with magnetic sensor, and when I open and close the door, it sends the proper contact status (“OPEN” when I open the door, “CLOSED” when I close the door), so this aspect of it works great.
However, as soon as the device is polled, it returns a different status, which is interpreted as “OPEN” even when the door is closed. So, after I close it, it switches (properly) to CLOSED state, but the next time it’s polled, it reverts to OPEN even though the door is still closed.

Here is a log (with non-relevant lines removed) showing what I mean:

(3D.CC.81 is the Insteon address of my IOLinc)

2017-01-08 13:31:48.533 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 3D.CC.81 is empty!
2017-01-08 13:33:02.512 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x00|
2017-01-08 13:33:02.520 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x00|
2017-01-08 13:33:02.556 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincContact->OpenedContactHandler cmd1:0x11 group 1/1:IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x00|
2017-01-08 13:33:02.560 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:IOLincContact publishing: OPEN
2017-01-08 13:33:02.571 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x00|
2017-01-08 13:33:02.581 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincSwitch->NoOpMsgHandler cmd1:0x11 group 1/1:IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x00|
2017-01-08 13:33:02.587 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T13:33:02
2017-01-08 13:33:02.950 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x11|command2:0x01|
2017-01-08 13:33:02.955 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x11|command2:0x01|
2017-01-08 13:33:02.960 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x11|command2:0x01|
2017-01-08 13:33:02.966 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T13:33:02
2017-01-08 13:33:03.134 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:11.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 13:33:03.139 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:11.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 13:33:03.143 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:11.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 13:33:03.148 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T13:33:03
2017-01-08 13:33:29.243 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x00|
2017-01-08 13:33:29.258 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x00|
2017-01-08 13:33:29.272 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincContact->ClosedContactHandler cmd1:0x13 group 1/1:IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x00|
2017-01-08 13:33:29.279 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:IOLincContact publishing: CLOSED
2017-01-08 13:33:29.299 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x00|
2017-01-08 13:33:29.308 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincSwitch->NoOpMsgHandler cmd1:0x13 group 1/1:IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x00|
2017-01-08 13:33:29.313 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T13:33:29
2017-01-08 13:33:29.683 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x13|command2:0x01|
2017-01-08 13:33:29.688 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x13|command2:0x01|
2017-01-08 13:33:29.692 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x13|command2:0x01|
2017-01-08 13:33:29.697 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T13:33:29
2017-01-08 13:33:29.878 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:13.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 13:33:29.883 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:13.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 13:33:29.889 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:13.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 13:33:29.894 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T13:33:29
2017-01-08 13:36:48.034 [DEBUG] [eonplm.internal.device.InsteonDevice] - qe taken off direct: IOLincContact(1:1:4) OUT:Cmd:0x62|toAddress:3D.CC.81|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2017-01-08 13:36:48.040 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (500): OUT:Cmd:0x62|toAddress:3D.CC.81|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2017-01-08 13:36:48.371 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x03|command2:0x00|
2017-01-08 13:36:48.375 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincContact DIRECT_ACK: q:QUERY_PENDING cmd: 80
2017-01-08 13:36:48.381 [DEBUG] [lm.internal.device.MessageDispatcher] - changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x03|command2:0x00|
2017-01-08 13:36:48.386 [INFO ] [onplm.internal.device.MessageHandler] - ContactRequestReplyHandler: set contact 3D.CC.81 to: OPEN
2017-01-08 13:36:48.390 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:IOLincContact publishing: OPEN
2017-01-08 13:36:48.396 [DEBUG] [lm.internal.device.MessageDispatcher] - defdisp: 3D.CC.81:IOLincContact set status to: QUERY_ANSWERED
2017-01-08 13:36:48.403 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T13:36:48
2017-01-08 13:36:48.533 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 3D.CC.81 is empty!
your code goes here

At the beginning of the log, I open the door, and the log shows that the IOLIncContact->OpenedContactHandler receives the cmd1:0x11 and correctly published status as OPEN. (at 13:33:02.556 in the timestamp).

At 13:33:29, I close the garage door, and the IOLincContact->ClosedContactHandler receives the cmd1:0x13, and publishes the correct status as CLOSED.

Now, where the problem begins: at 13:36:48 (which is the next polling interval) the device is polled regarding contact status, and appears to return a command1:0x19. At 13:36:48.386, the ContactRequestReplyHandler changes the status of the contact to OPEN, even though it is still physically closed and nothing at the hardware side (the door, the magnetic contact etc) has changed.

I suspect this has to do with the device sending a different command (0x19) when polled about it’s status, rather than the open (0x11) or closed (0x13) commands it sends when something actually changes.

Is there a way to fix this? As it stands currently, my contact status only shows “CLOSED” correctly as soon as the door is closed, until the next polling interval, when the door status becomes OPEN regardless, forever after, until the next manual closing.

I am certainly not an expert in this stuff, though I have been using insteon for many years (new to Openhab, though) and I don’t know enough about Java to delve into the code and try and sort this out myself. If anyone can provide any suggestions to work around this, I would be glad to hear them. Is this a bug in the ContactRequestReplyHandler?

Thanks for any input,

Sean

2

Maybe you have your switch wired backwards. If it’s a normally open switch, is it wired as such? Or if it’s a normally closed, is it wired as a normally closed?

3

Well, I don’t think it’s wired backwards. The IOLinc can be configured to work either way, I believe. (With NO or NC contacts) The problem I’m having is not that it sends the wrong status when I open and close the door. When I open and close the door myself, it sends the proper signal. It’s only when the openhab is polling the switch that it reads incorrectly. (Polling, meaning querying the contacts about their status every 5 minutes, as opposed to the device sending it’s status when it changes).
It would seem to me that if I had it wired backwards, it would send “CLOSED” when I open it, and “OPEN” when I close it. It doesn’t - it sends the proper status. For example, if I open the door, it sends “OPEN”. Then, when I close the door, it sends “CLOSED”. But, five minutes after I’ve closed the door, it suddenly changes the status to “OPEN” again even though the door hasn’t changed. I hope that makes sense?

Sean

4

OK, A little more investigation done, looking through the log files.

Here is the excerpt from the log file (Sorry these attachments are long!)

2017-01-08 19:46:48.051 [DEBUG] [eonplm.internal.device.InsteonDevice] - qe taken off direct: IOLincContact(1:1:4) OUT:Cmd:0x62|toAddress:3D.CC.81|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2017-01-08 19:46:48.060 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (500): OUT:Cmd:0x62|toAddress:3D.CC.81|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2017-01-08 19:46:48.416 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x03|command2:0x00|
2017-01-08 19:46:48.419 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincContact DIRECT_ACK: q:QUERY_PENDING cmd: 80
2017-01-08 19:46:48.424 [DEBUG] [lm.internal.device.MessageDispatcher] - changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x03|command2:0x00|
2017-01-08 19:46:48.434 [INFO ] [onplm.internal.device.MessageHandler] - ContactRequestReplyHandler: set contact 3D.CC.81 to: OPEN
2017-01-08 19:46:48.441 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:IOLincContact publishing: OPEN
2017-01-08 19:46:48.444 [DEBUG] [lm.internal.device.MessageDispatcher] - defdisp: 3D.CC.81:IOLincContact set status to: QUERY_ANSWERED
2017-01-08 19:46:48.452 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T19:46:48
2017-01-08 19:46:48.550 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 3D.CC.81 is empty!
2017-01-08 19:47:16.709 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x00|
2017-01-08 19:47:16.714 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x00|
2017-01-08 19:47:16.722 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincContact->OpenedContactHandler cmd1:0x11 group 1/1:IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x00|
2017-01-08 19:47:16.726 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:IOLincContact publishing: OPEN
2017-01-08 19:47:16.736 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x00|
2017-01-08 19:47:16.747 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincSwitch->NoOpMsgHandler cmd1:0x11 group 1/1:IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x00|
2017-01-08 19:47:16.753 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T19:47:16
2017-01-08 19:47:17.146 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x11|command2:0x01|
2017-01-08 19:47:17.151 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x11|command2:0x01|
2017-01-08 19:47:17.156 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x11|command2:0x01|
2017-01-08 19:47:17.161 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T19:47:17
2017-01-08 19:47:17.336 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:11.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 19:47:17.341 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:11.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 19:47:17.346 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:11.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 19:47:17.351 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T19:47:17
2017-01-08 19:51:48.051 [DEBUG] [eonplm.internal.device.InsteonDevice] - qe taken off direct: IOLincContact(1:1:4) OUT:Cmd:0x62|toAddress:3D.CC.81|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2017-01-08 19:51:48.057 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (500): OUT:Cmd:0x62|toAddress:3D.CC.81|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2017-01-08 19:51:48.391 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x03|command2:0x01|
2017-01-08 19:51:48.399 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincContact DIRECT_ACK: q:QUERY_PENDING cmd: 80
2017-01-08 19:51:48.410 [DEBUG] [lm.internal.device.MessageDispatcher] - changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x03|command2:0x01|
2017-01-08 19:51:48.419 [INFO ] [onplm.internal.device.MessageHandler] - ContactRequestReplyHandler: set contact 3D.CC.81 to: CLOSED
2017-01-08 19:51:48.427 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:IOLincContact publishing: CLOSED
2017-01-08 19:51:48.448 [DEBUG] [lm.internal.device.MessageDispatcher] - defdisp: 3D.CC.81:IOLincContact set status to: QUERY_ANSWERED
2017-01-08 19:51:48.459 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T19:51:48
2017-01-08 19:51:48.550 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 3D.CC.81 is empty!
2017-01-08 19:52:27.945 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x00|
2017-01-08 19:52:27.950 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x00|
2017-01-08 19:52:27.960 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincContact->ClosedContactHandler cmd1:0x13 group 1/1:IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x00|
2017-01-08 19:52:27.966 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:IOLincContact publishing: CLOSED
2017-01-08 19:52:27.977 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x00|
2017-01-08 19:52:28.001 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincSwitch->NoOpMsgHandler cmd1:0x13 group 1/1:IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x00|
2017-01-08 19:52:28.007 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T19:52:28
2017-01-08 19:52:28.381 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x13|command2:0x01|
2017-01-08 19:52:28.387 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x13|command2:0x01|
2017-01-08 19:52:28.393 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x45=ALL_LINK_CLEANUP:1:1|command1:0x13|command2:0x01|
2017-01-08 19:52:28.399 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T19:52:28
2017-01-08 19:52:28.576 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:13.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 19:52:28.582 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:13.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 19:52:28.588 [DEBUG] [lm.internal.device.MessageDispatcher] - all link message: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:13.02.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00|
2017-01-08 19:52:28.594 [DEBUG] [eonplm.internal.device.DeviceFeature] - 3D.CC.81:GenericLastTime publishing: 2017-01-08T19:52:28
2017-01-08 19:56:48.051 [DEBUG] [eonplm.internal.device.InsteonDevice] - qe taken off direct: IOLincContact(1:1:4) OUT:Cmd:0x62|toAddress:3D.CC.81|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2017-01-08 19:56:48.056 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (500): OUT:Cmd:0x62|toAddress:3D.CC.81|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2017-01-08 19:56:48.382 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x03|command2:0x00|
2017-01-08 19:56:48.386 [DEBUG] [lm.internal.device.MessageDispatcher] - 3D.CC.81:IOLincContact DIRECT_ACK: q:QUERY_PENDING cmd: 80
2017-01-08 19:56:48.391 [DEBUG] [lm.internal.device.MessageDispatcher] - changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:3D.CC.81|toAddress:3C.4C.6D|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x03|command2:0x00|
2017-01-08 19:56:48.395 [INFO ] [onplm.internal.device.MessageHandler] - ContactRequestReplyHandler: set contact 3D.CC.81 to: OPEN

So, initial state at the beginning of this log segment is that the door is closed, and contact shoud be reading as “CLOSED”.
At timestamp 19:46:48.060 we can see Openhab polling the IOLinc (cmd1 0x19, cmd2 0x01).
19:46:48.416 IOLinc sends back reply, cmd1 0x03 cmd2 0x00
19:46:48.434 ContactRequestReplyHandler sets status to “OPEN” (even though it is actually closed, as mentioned in my original post)

19:47:16 I Actually go and open the door. It is now physically open
19:47:16.709 IOLinc sends cmd1 0x11 cmd2 0x00 (it sends this on its own, it hasn’t been polled by Openhab)
19:47:16.722 OpenedContactHandler correctly changes status to “OPEN” (well, it was OPEN already, but it publishes it again)
Now, door is open, and status is OPEN. All is well in the world! This is how I want it to work, and how I imagine is should work.

19:51:48.057 Openhab is polling the IOLinc again, to get it’s status
19:51:48.391 IOLinc responds with cmd1 0x03 cmd2 0x01
19:51:48.419 ContactRequestReplyHandler interprets this as CLOSED, and changes status to CLOSED (even though the door is still open)

19:52:27 I actually go and close the door, so it is now physically closed
19:52:27.945 IOLinc sends cmd1 0x13 cmd2 0x00 (again, it sends this on it’s own, because the actual physical magnetic contact has changed state)
19:52:27.960 ClosedContactHandler correctly changes status to “CLOSED” in response to the above message.
Now door is closed, status is CLOSED and once again briefly all is well in the world. Alas, not for long.

19:56:48.056 Openhab again polls the device for status.
19:56:48.382 IOLinc responds with cmd1 0x03 cmd2 0x00
19:56:48.395 ContactRequestReplyHandler sets contact status (incorrectly) to OPEN again, even though door is still closed.

So, after all this, is there a way I can change the code so that when ContactRequestReplyHandler sees the response 0x03 0x00 it sets the status to CLOSED rather than OPEN, and when is sees the response 0x03 0x01 it sets it to OPEN rather than CLOSED?
If someone can even point me in the right direction as to which file to edit, I imagine I can do this, but there are so many files, I don’t even know where to start to look.

Of course the bigger issue here is: It would appear from other posts that the code as-is works for some people. I suspect this has to do with one of maybe two factors: (1) whether one is using a normally open (NO) or a normally closed (NC) contact attached to their IOLinc
(2) How a person set up their IOLinc. An excerpt from the IOLinc manual:

NOTE: During linking, you will have the option to turn on remote INSTEON devices when either the connected sensor is closed or
when it is opened. Once this is programmed, the opposite action will trigger an OFF command. For example, if you program an
ON command to be sent when the I/O Linc connected sensor is closed, opening the sensor will trigger an OFF command.

Perhaps the different ways of setting it up lead to different responses to polling? Maybe in the insteon binding (or somewhere?) there could be an option to have the polling status “normal” or “inverse”?

I don’t really want to change my hardware setup, change how I’ve wired the magnetic contact, and how the IOLinc responds, because it means climbing up a ladder, re-wiring the sensor, and changing the database table for the IOLinc. (because it also is set to directly turn on a light when the door opens, and this works flawlessly for me now. Only the Openhab polling seems to break.) I guess one work around,suitable only for my setup, would be to use the status of the light it controls as a surrogate for whether the door is open or closed, but again this seems like a kludge where the proper solution is to have the software configurable for the different hardware setups that are possible with the IOLinc?

If anyone has any thoughts on this, I’d be happy to listen!

Sean

5

This looks similar to an issue somebody had about a year ago at Insteon IO Linc Garage Door troubles. @Bernd_Pfrommer replied with the following:

@craigh modified the message handlers and flipped the open and close handlers around and it appears to fix the problem.

@trav70 can you try and create your own device type and see if it fixes the problem? There are instructions at: Insteon PLM Binding · openhab/openhab1-addons Wiki · GitHub

6

@trav70, have you tried unlinking the IO Link and hub/plm, and then linking when its in the correct position? You don’t need to re-link the light.

7

Rob,

I wonder if you may be on to something there, with having linked it to the PLM in the “incorrect” starting position. The manual for the IOLinc states,

Put your sensor into the state you want to use to trigger I/O Linc to send an ON command. For example, if you want closing
the sensor to send an ON command, close the sensor

I am almost certain I had the contact in the opposite position when I linked it (i.e., the contact state that I use to indicate “door closed, light off”). And that may have something to do with my issues.

I did some more investigating last night and this afternoon (after work). My setup is currently as follows:
I have a magnetic contact on the wall near the top of the door, with magnet on the door, such that when the garage door is closed, the magnet is next to the contact. When the door opens, the magnet pulls away from the contact and it changes state. Currently, it is wired so that the magnetic contact is NC. (Meaning, when the door is open, the contacts are closed). The IOlinc is set so that when it detects a transition to this state, it sends an ON command to the overhead garage lights. When the door closes, the magnet comes back into proximity, the contacts open (since it’s NC) and the IOlinc interprets this state to send the OFF command to the lights.

I did find the file where this is all handled, too, by looking at the Java source code - it’s in the MessageHandler.java file, and that’s where OpenedContactHandler, ClosedContactHandler, and ContactRequestReplyHandler live. (The device.xml file seems to only tell the software which handler to call depending on the command received, so I’m not sure it could be of much use in my case.)

So,
It would seem that my “software” options (with helpful suggestions from you, thank you) include:

(1) re-writing the device type xml file (the only thing I could see myself doing here would be to replace the ContactRequestReplyHandler with a null handler, so that the MessageHandler ignores whatever command is returned with polling, and only changes state on the OpenedContactHandler and ClosedContactHandler calls, effectively disabling polling)

(2) re-writing the MessageHandler.java source to change this line

OpenClosedType oc = (cmd2 == 0) ? OpenClosedType.OPEN : OpenClosedType.CLOSED;

to:

OpenClosedType oc = (cmd2 == 1) ? OpenClosedType.OPEN : OpenClosedType.CLOSED;

which I believe would solve my problem by inverting the states only on polling, at the expense of giving me a different version than anybody else in the world, which would likely break again next time I updated the binding!

Since I determined it would take me quite some time to learn how to download the whole binding source, learn how to use Eclipse with java, learn how to recompile all the source into bytecode, etc… I determined that option 2 would be too time-consuming, though it would be educational.
I also didn’t want to just disable the polling, so I determined that option 1 was suboptimal (if I even could have achieved that. Not sure if it’s possible to do that by just modifying that file.)

So, in the end, looking at the time investment involved, I opted to change the hardware setup (even thought it meant climbing a ladder in sub-zero temperatures in my garage - gotta love living in the North!)
I re-wired my contact to be NO (luckily I had the foresight to use a contact that had wires for both NO and NC usage, sparing me the purchase of another contact) and re-paired the IOlinc with the light to achieve the correct function.

As an observation, to potentially help anyone else who may have the same problem I had, here are some thoughts.
It would seem there are two different hardware configurations possible:

-open contacts sends an “ON” signal
-closed contacts sends an “ON” signal.

The current binding seems to work well if the setup is of the “open contacts sends an ON signal” variety, but not if it’s setup the other way. (Correct me if my assumption is flawed here, please, anyone, I’m a bit fatigued and my brain may not be working logically).
By switching my hardware from the second case to the first case, I got it to work.

I almost wonder if the series of commands: cmd1 0x11 cmd2 0x00 actually represents the IOLinc sending an “ON” to the responder(s) rather than reporting the contacts closing, because I got the same commands sent when I had it wired NC and NO. Similarly, cmd1 0x13 cmd2 0x00 would indicate that IOLinc sent an “OFF” command, not that the contacts opened.
Then, perhaps the commands cmd1 0x?? cmd2 0x00 indicates contacts open, cmd1 0x?? cmd2 0x01 indicates contacts closed (rather than responder device on/off) In this manner, you can have an OpenedContactHandler telling you one thing followed immediately by ContactRequestReplyHandler telling you another - because they are reporting two different things? (contact state vs responder device state)

Anyways, these are just my tired musings, which may provide food for thought for anyone else having these sorts of issues with the IOLinc.

Thanks all,

Sean

8

Hi Sean,

I’m glad you got it to work. If you have time, can you possibly update the wiki for InsteonPLM with pointers with making sure the contact is in the correct position when pairing?

Thanks,

Rob

9

Rob, I could probably do that if I knew how!
This is the link to the Wiki, that I can find:

https://github.com/openhab/openhab/wiki/Insteon-PLM-Binding’

Is this the one you mean? I looked at it, but have no idea how to go about modifying it. If you can point me in the right direction, I’ll see what I can do

Thanks again,

Sean

10

You’ll first need a GitHub account, then after you’ve logged in, there should be an edit button in the right hand column. I updated the documentation with a note about linking when the door is in the wrong position. Feel free to edit my changes. https://github.com/openhab/openhab/wiki/Insteon-PLM-Binding#io-linc-garage-door-openers