Insteon polling seems to have turned a light on and then off at separate intervals

twinotter · September 17, 2018, 9:20am

Platform information:
- Hardware: Raspberry Pi 2B+
- OS: Raspbian
- openHAB version: 2.1.0

Insteon polling seems to have turned on a keypad switch on one poll interval, then turned it off five minutes later at a subsequent interval. Two rules caused another light to turn on and a music player to turn on… both turned back off at the subsequent polls. Those rules did what they were supposed to do, but the initial turn-on shouldn’t have happened.

Looking at the logs, Polling is happening normally. Then statistic collection happens. For the rest of that polling session, all the switches are inverted. When the next polling happens, things are set back to their original state.

Any ideas why it would? It really creeped out my wife!

Please post configurations (if applicable):
- Items configuration related to the issue
- Sitemap configuration related to the issue
- Rules code related to the issue
- Services configuration related to the issue
If logs where generated please post these here using code fences:

2018-09-17 03:13:52.191 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 20.88.FC to ON
2018-09-17 03:14:19.495 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 20.76.82 to OFF
2018-09-17 03:14:46.700 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 1F.EE.1B to OFF
2018-09-17 03:15:00.045 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - Item: backhall got command ON
2018-09-17 03:15:00.049 [INFO ] [onplm.internal.device.CommandHandler] - LightOnOffCommandHandler: sent msg to switch 20.88.FC to on
2018-09-17 03:15:00.055 [INFO ] [onplm.internal.device.CommandHandler] - Sending message to 20.88.FC
2018-09-17 03:15:00.388 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 20.88.FC to ON
2018-09-17 03:15:14.239 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 1F.EE.37 to OFF
2018-09-17 03:16:36.058 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9B.8C button 1 switched to OFF
2018-09-17 03:17:03.126 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 1F.ED.6F to OFF
2018-09-17 03:17:07.994 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - devices:  17 configured,   9 polling, msgs received:    20
2018-09-17 03:17:07.998 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 22.8E.02|keypadbuttonA->KeyPadButton3(0:1:6)|manualchangebuttonD->ManualChangeButton6(0:1:2)|keypadbuttonD->KeyPadButton6(0:1:6)|manualchangebuttonA->ManualChangeButton3(0:1:2)|keypadbuttonB->KeyPadButton4(0:1:6)|manualchangebuttonC->ManualChangeButton5(0:1:2)|keypadbuttonC->KeyPadButton5(0:1:6)|manualchangebuttonB->ManualChangeButton4(0:1:2)|button_group->KeyPadButtonGroup(0:0:0)|manualchange_button_group->ManualChangeButtonGroup(0:0:0)|loadswitchmanualchange->LoadSwitchManualChange(0:1:2)|loadswitchfastonoff->LoadSwitchFastOnOff(0:1:3)|fastonoff_button_group->FastOnOffButtonGroup(0:0:0)|fastonoffbuttonB->FastOnOffButton4(0:1:2)|fastonoffbuttonC->FastOnOffButton5(0:1:2)|lastheardfrom->GenericLastTime(0:0:0)|fastonoffbuttonD->FastOnOffButton6(0:1:2)|loadswitch->LoadSwitchButton(1:1:6)|fastonoffbuttonA->FastOnOffButton3(0:1:2) has not responded to polls for 601614 sec
2018-09-17 03:17:30.339 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 1F.EE.31 to OFF
**2018-09-17 03:17:57.612 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9A.BD button 3 switched to ON**
2018-09-17 03:17:57.620 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9A.BD button 4 switched to ON
2018-09-17 03:17:57.625 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9A.BD button 5 switched to OFF
2018-09-17 03:17:57.631 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9A.BD button 6 switched to OFF
2018-09-17 03:17:57.665 [INFO ] [eclipse.smarthome.model.script.rules] - diningroomC rule received. diningroomC State: [ON]
2018-09-17 03:17:57.762 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - Item: livingside got command ON
2018-09-17 03:17:57.768 [INFO ] [onplm.internal.device.CommandHandler] - X10OnOffCommandHandler: sent msg to switch A.2 ON
2018-09-17 03:17:57.787 [INFO ] [nhab.binding.mpd.internal.MpdBinding] - Executed command 'play' for player '1'
2018-09-17 03:17:57.806 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - Item: livingroom got command ON
2018-09-17 03:17:57.810 [INFO ] [onplm.internal.device.CommandHandler] - LightOnOffCommandHandler: sent msg to switch 1F.EE.31 to on
2018-09-17 03:17:57.813 [INFO ] [onplm.internal.device.CommandHandler] - Sending message to 1F.EE.31
2018-09-17 03:17:59.201 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 1F.EE.31 to ON
2018-09-17 03:17:59.724 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9A.BD button 1 switched to OFF
2018-09-17 03:18:52.744 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 20.88.FC to ON
2018-09-17 03:19:19.487 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 20.76.82 to OFF
2018-09-17 03:19:46.709 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 1F.EE.1B to OFF
2018-09-17 03:20:00.058 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - Item: backhall got command ON
2018-09-17 03:20:00.068 [INFO ] [onplm.internal.device.CommandHandler] - LightOnOffCommandHandler: sent msg to switch 20.88.FC to on
2018-09-17 03:20:00.076 [INFO ] [onplm.internal.device.CommandHandler] - Sending message to 20.88.FC
2018-09-17 03:20:00.409 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 20.88.FC to ON
2018-09-17 03:20:14.249 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 1F.EE.37 to OFF
2018-09-17 03:21:36.067 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9B.8C button 1 switched to OFF
2018-09-17 03:22:03.125 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 1F.ED.6F to OFF
2018-09-17 03:22:30.338 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 1F.EE.31 to ON
2018-09-17 03:22:57.615 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9A.BD button 3 switched to OFF
2018-09-17 03:22:57.620 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9A.BD button 4 switched to OFF
2018-09-17 03:22:57.633 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9A.BD button 5 switched to ON
2018-09-17 03:22:57.640 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9A.BD button 6 switched to ON
2018-09-17 03:22:57.698 [INFO ] [eclipse.smarthome.model.script.rules] - diningroomC rule received. diningroomC State: [OFF]
2018-09-17 03:22:57.729 [INFO ] [nhab.binding.mpd.internal.MpdBinding] - Executed command 'stop' for player '1'
2018-09-17 03:22:57.751 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - Item: livingroom got command OFF
2018-09-17 03:22:57.754 [INFO ] [onplm.internal.device.CommandHandler] - LightOnOffCommandHandler: sent msg to switch 1F.EE.31 off
2018-09-17 03:22:57.757 [INFO ] [onplm.internal.device.CommandHandler] - Sending message to 1F.EE.31
2018-09-17 03:22:57.771 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - Item: livingside got command OFF
2018-09-17 03:22:57.776 [INFO ] [onplm.internal.device.CommandHandler] - X10OnOffCommandHandler: sent msg to switch A.2 OFF
2018-09-17 03:22:58.132 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 1F.EE.31 to OFF
2018-09-17 03:22:59.717 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: dev 2B.9A.BD button 1 switched to OFF
2018-09-17 03:23:53.245 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 20.88.FC to ON

Thedannymullen · September 17, 2018, 11:56am

That’s interesting that your tracked it down to a polling loop. I had a similar issue and I have not been able to track it down.

My case is similar as sometimes lights would go on or off at random. I don’t know the why, but I know it appeared as if the keypad was having ghost presses. I say this because the light on the keypad button would turn on/off as if someone pressed it.

For right now I disabled all my keypad buttons except one. I have not seen this issue on that button. I was unable to trouble shoot and see if openHAB was actually commanding the button on or off. Any help that can be provided would probably help me also.

What hardware interface to openHAB do you have? Is it a hub or plm?

twinotter · September 17, 2018, 1:22pm

It’s a USB Hub - #2431U.

Thedannymullen · September 17, 2018, 1:25pm

Thanks! I was curious I use the not reworks one 2245.

Maybe someone will have some solutions. I was suspecting my keypad as defective until you posted.

mjcumming · September 18, 2018, 1:04pm

I have seen this problem using a different home automation app. Insteon messages can be corrupted and I believe this is what is happening in these instances.

I have tested this using standard definition Insteon messages peeking the same byte from a device’s memory - I have seen in some instances the returned value being wrong in about 10% of cases. Insteon standard definition messages do not have a checksum so there is no way to know if the message was corrupted. Extended definition messages (some of them) incorporate a checksum to avoid this.

twinotter · September 18, 2018, 6:00pm

Cool. That’s what I was thinking was happening when I saw the polling and statistic collection happening at the same time. I was thinking that maybe there is a race condition in the code… but don’t really know where to begin to look…

When you saw it previously, was it just a test-bed kind of situation or did you ever see it in the wild? I think it may be happening somewhat frequently for me… though this is the first that I have log-entry proof of…

mjcumming · September 19, 2018, 2:31am

Happens in the wild. My home, about 100 insteon devices. Mainly discovered the issue with Insteon engine 1 devices (which only support SD commands). Issue mainly apparent when trying to read a device link database using peek commands. But corruption can occur on any command and cause weird things like lights turning on in the middle of the night… My observations is this happens on devices that are farther away from the PLM requiring multiple hops for the command to get to the device. Doesn’t seem to happen with the RF devices…

twinotter · September 19, 2018, 11:58am

These are all dual band devices…

Perhaps there should be a semaphore wrapper around the communication with the PLM? I haven’t dug into the code yet. Are there multiple threads running that have access to communication with the PLM?

BTW, what do you use to manage the links on your 100ish devices? I started with the PC software that’s been discontinued. Did a bunch manually. But really just want something that’s script-able. I’ve used the terminal program and sorta envisioned writing a wrapper for that… but does a tool like that already exist?

mjcumming · September 19, 2018, 12:33pm

I am using the ISY99 to manage Insteon devices and scenes. It sits between OH and the PLM. Uses a different binding.

The ISY is really necessary in a larger Insteon network - devices fail and an easy way to replace them makes managing the network helps.

In OH, I mostly reference scenes rather than Insteon devices directly. That way if (when) a device fails, I just need to use the “replace device” feature on the ISY99 and not change code in OH.