Strange behavior with altsteon/keypadlinc

Hey guys,

I have an 8-button KPL setup that is exhibiting some unusual behavior. The main (load) switch is setup to control my undercabinet lighting via a scene. (The switch doesn’t actually have a load attached.) This seems straight forward enough, but frequently when I use the switch, the scene triggers (the lights turn on, for example), but then a few seconds later it reverts (the lights turn back on, or vice versa). Sometimes this will occur repeatedly and indefinitely, sometimes it will just happen once or a few times.

Any thoughts on what could be causing this?

This is the luup running when the scene is triggered (On):

luup.call_action("urn:upnp-org:serviceId:Dimming1", "SetLoadLevelTarget", {newLoadlevelTarget = "100"},46)

This is the luup running when the scene is triggered (Off):

luup.call_action("urn:upnp-org:serviceId:Dimming1", "SetLoadLevelTarget", {newLoadlevelTarget = "0"},46)

Below is some log data where the issue is occurring. Here I think the button was pressed once, the light turned off and then back on:

50 01/02/15 10:33:14.234 luup_log:50: Parsing : 2C.05.10:008D,00,01,00 - LED follow mask for button/group 1 is 0. <0x2febc680> 50 01/02/15 10:33:14.235 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:14.237 luup_log:50: Parsing : 2C.05.10:008E,00,01,00 - LED off mask for button/group 1 is 0. <0x2febc680> 50 01/02/15 10:33:14.237 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:14.239 luup_log:50: Parsing : 2C.05.10:008F,00,01,20 - X10 house code for button/group 1 is 32. <0x2febc680> 50 01/02/15 10:33:14.251 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:14.253 luup_log:50: Parsing : 2C.05.10:0090,00,01,20 - X10 unit code for button/group 1 is 32. <0x2febc680> 50 01/02/15 10:33:14.254 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:14.256 luup_log:50: Parsing : 2C.05.10:0091,00,01,1C - Ramp rate for button/group 1 is 28. <0x2febc680> 50 01/02/15 10:33:14.256 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:14.258 luup_log:50: Parsing : 2C.05.10:0092,00,01,FE - On level for button/group 1 is 254. <0x2febc680> 50 01/02/15 10:33:14.258 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:14.307 luup_log:50: Parsing : 2C.05.10:0093,00,01,05 - Global LED brightness for button/group 1 is 5. <0x2febc680> 50 01/02/15 10:33:14.307 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:14.309 luup_log:50: Parsing : 2C.05.10:0094,00,01,00 - Associated non-toggle bitmap for button/group 1 is 0. <0x2febc680> 50 01/02/15 10:33:14.353 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:14.355 luup_log:50: Parsing : 2C.05.10:0095,00,01,0F - LED state for button/group 1 is 15. <0x2febc680> 50 01/02/15 10:33:14.356 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:14.358 luup_log:50: Parsing : 2C.05.10:0096,00,01,00 - X-10 all bitmap for button/group 1 is 0. <0x2febc680> 50 01/02/15 10:33:14.358 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:14.414 luup_log:50: Parsing : 2C.05.10:0097,00,01,00 - Non-toggle bitmap for button/group 1 is 0. <0x2febc680> 50 01/02/15 10:33:14.415 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:14.417 luup_log:50: Parsing : 2C.05.10:0098,00,01,00 - Trigger all-link bitmap for button/group 1 is 0. <0x2febc680> 50 01/02/15 10:33:14.418 luup_log:50: Sending to child id 51 (2C.05.10) <0x2febc680> 50 01/02/15 10:33:17.602 luup_log:50: Parsing : 2B.A7.14:0009,00,01 - 2B.A7.14 button/group 1 is off. <0x2febc680> 50 01/02/15 10:33:17.602 luup_log:50: Sending to child id 71 (2B.A7.14) <0x2febc680> 06 01/02/15 10:33:17.603 Device_Variable::m_szValue_set device: 71 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 1 now: 0 #hooks: 2 upnp: 0 v:0xf7beb8/NONE duplicate:0 <0x2febc680> 07 01/02/15 10:33:17.603 Event::Evaluate 28 Kitchen 8 Button Scene Controller Main On scene Undercabinet Lights On is false repeat 0/-1 <0x2febc680> 07 01/02/15 10:33:17.604 Event::Evaluate 29 Kitchen KPL Off scene Undercabinet Lights Off is true users:(null) allow:1 <0x2febc680> 08 01/02/15 10:33:17.604 Scene::RunScene running 29 Undercabinet Lights Off <0x2febc680> 08 01/02/15 10:33:17.605 JobHandler_LuaUPnP::HandleActionRequest device: 46 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x2febc680> 08 01/02/15 10:33:17.605 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=0 <0x2febc680> 50 01/02/15 10:33:17.606 luup_log:26: Philips Hue Controller: 46 <0x2febc680> 50 01/02/15 10:33:17.606 luup_log:26: Philips Hue Controller: *** DIM device: 46 value: 0 altid:5 <0x2febc680> 50 01/02/15 10:33:17.607 luup_log:26: Philips Hue Controller: Post: {"on":false} <0x2febc680> 06 01/02/15 10:33:17.906 Device_Variable::m_szValue_set device: 46 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 100 now: 0 #hooks: 2 upnp: 0 v:0xf95e00/NONE duplicate:0 <0x2febc680> 06 01/02/15 10:33:17.907 Device_Variable::m_szValue_set device: 46 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 1 now: 0 #hooks: 0 upnp: 0 v:0xf7beb8/NONE duplicate:0 <0x2febc680> 50 01/02/15 10:33:18.892 luup_log:50: Parsing : 2B.A7.14:0024,00,FF - Light brightness is 255. <0x2febc680> 50 01/02/15 10:33:18.893 luup_log:50: Sending to child id 71 (2B.A7.14) <0x2febc680> 06 01/02/15 10:33:18.893 Device_Variable::m_szValue_set device: 71 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 100 now: 100 #hooks: 0 upnp: 0 v:0xf95e00/NONE duplicate:1 <0x2febc680> 06 01/02/15 10:33:18.894 Device_Variable::m_szValue_set device: 71 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 2 upnp: 0 v:0xf7beb8/NONE duplicate:0 <0x2febc680> 07 01/02/15 10:33:18.894 Event::Evaluate 28 Kitchen 8 Button Scene Controller Main On scene Undercabinet Lights On is true users:(null) allow:1 <0x2febc680> 08 01/02/15 10:33:18.894 Scene::RunScene running 28 Undercabinet Lights On <0x2febc680> 08 01/02/15 10:33:18.895 JobHandler_LuaUPnP::HandleActionRequest device: 71 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x2febc680> 08 01/02/15 10:33:18.895 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=100 <0x2febc680> 50 01/02/15 10:33:18.896 luup_log:50: Setting dimmer to 100 <0x2febc680> 50 01/02/15 10:33:18.896 luup_log:50: Sending (setloadleveltarget) : "2B.A7.14" instant_dim 100 <0x2febc680> 08 01/02/15 10:33:18.898 JobHandler_LuaUPnP::HandleActionRequest device: 46 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x2febc680> 08 01/02/15 10:33:18.898 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=100 <0x2febc680> 50 01/02/15 10:33:18.899 luup_log:26: Philips Hue Controller: 46 <0x2febc680> 50 01/02/15 10:33:18.899 luup_log:26: Philips Hue Controller: *** DIM device: 46 value: 100 altid:5 <0x2febc680> 50 01/02/15 10:33:18.981 luup_log:26: Philips Hue Controller: Post: {"on":true,"bri":254} <0x2febc680> 06 01/02/15 10:33:19.179 Device_Variable::m_szValue_set device: 46 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 0 now: 100 #hooks: 2 upnp: 0 v:0xf95e00/NONE duplicate:0 <0x2febc680> 06 01/02/15 10:33:19.273 Device_Variable::m_szValue_set device: 46 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 0 upnp: 0 v:0xf7beb8/NONE duplicate:0 <0x2febc680> 08 01/02/15 10:33:19.274 JobHandler_LuaUPnP::HandleActionRequest device: 47 service: urn:intvelt-com:serviceId:HueColors1 action: SetPreset <0x2febc680> 08 01/02/15 10:33:19.274 JobHandler_LuaUPnP::HandleActionRequest argument Preset=1 <0x2febc680> 50 01/02/15 10:33:19.275 luup_log:26: Philips Hue Controller: >>> Device:47 Lamp nr:5 To preset:1 <0x2febc680> 50 01/02/15 10:33:19.276 luup_log:26: Philips Hue Controller: level:100 on:1 <0x2febc680> 50 01/02/15 10:33:19.276 luup_log:26: Philips Hue Controller: Post: {"xy":[0.4567,0.3481]} <0x2febc680> 06 01/02/15 10:33:19.376 Device_Variable::m_szValue_set device: 47 service: urn:intvelt-com:serviceId:HueColors1 variable: CurrentPreset was: 1 now: 1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2febc680> 50 01/02/15 10:33:19.666 luup_log:26: Philips Hue Controller: Got JSON on get username: {"state": {"on":true,"bri":254,"hue":57359,"sat":78,"xy":[0.4567,0.3481],"alert":"none","effect":"none","colormode":"xy","reachable":true}, "type": "Color light", "name": "Undercabinet", "modelid": "LST001", "swversion": "66010400", "pointsymbol": { "1":"none", "2":"none", "3":"none", "4":"none", "5":"none", "6":"none", "7":"none", "8":"none" }} <0x2febc680> 50 01/02/15 10:33:19.666 luup_log:26: Philips Hue Controller: Response received for light state <0x2febc680> 06 01/02/15 10:33:19.667 Device_Variable::m_szValue_set device: 26 service: urn:intvelt-com:serviceId:HueController1 variable: LinkStatus was: Hue hub is up and linked now: Hue hub is up and linked #hooks: 0 upnp: 0 v:0xfcc330/NONE duplicate:1 <0x2febc680> 50 01/02/15 10:33:19.667 luup_log:26: Philips Hue Controller: Updating for light <0x2febc680> 06 01/02/15 10:33:19.668 Device_Variable::m_szValue_set device: 47 service: urn:intvelt-com:serviceId:HueColors1 variable: ColorTemperature was: 0 now: 0 #hooks: 0 upnp: 0 v:0xff9438/NONE duplicate:1 <0x2febc680> 06 01/02/15 10:33:19.668 Device_Variable::m_szValue_set device: 47 service: urn:intvelt-com:serviceId:HueColors1 variable: Hue was: 0 now: 0 #hooks: 0 upnp: 0 v:0xff9fc8/NONE duplicate:1 <0x2febc680> 06 01/02/15 10:33:19.668 Device_Variable::m_szValue_set device: 47 service: urn:intvelt-com:serviceId:HueColors1 variable: Saturation was: 0 now: 0 #hooks: 0 upnp: 0 v:0xff9fa8/NONE duplicate:1 <0x2febc680> 08 01/02/15 10:33:19.669 JobHandler_LuaUPnP::HandleActionRequest device: 46 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x2febc680> 08 01/02/15 10:33:19.720 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=100 <0x2febc680> 50 01/02/15 10:33:19.720 luup_log:26: Philips Hue Controller: 46 <0x2febc680> 50 01/02/15 10:33:19.721 luup_log:26: Philips Hue Controller: *** DIM device: 46 value: 100 altid:5 <0x2febc680> 50 01/02/15 10:33:19.722 luup_log:26: Philips Hue Controller: Post: {"on":true,"bri":254} <0x2febc680> 06 01/02/15 10:33:19.875 Device_Variable::m_szValue_set device: 46 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 100 now: 100 #hooks: 2 upnp: 0 v:0xf95e00/NONE duplicate:1 <0x2febc680> 06 01/02/15 10:33:19.876 Device_Variable::m_szValue_set device: 46 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 1 now: 1 #hooks: 0 upnp: 0 v:0xf7beb8/NONE duplicate:1 <0x2febc680> 08 01/02/15 10:33:19.877 JobHandler_LuaUPnP::HandleActionRequest device: 47 service: urn:intvelt-com:serviceId:HueColors1 action: SetPreset <0x2febc680> 08 01/02/15 10:33:19.877 JobHandler_LuaUPnP::HandleActionRequest argument Preset=1 <0x2febc680> 50 01/02/15 10:33:19.878 luup_log:26: Philips Hue Controller: >>> Device:47 Lamp nr:5 To preset:1 <0x2febc680> 50 01/02/15 10:33:19.878 luup_log:26: Philips Hue Controller: level:100 on:1 <0x2febc680> 50 01/02/15 10:33:19.879 luup_log:26: Philips Hue Controller: Post: {"xy":[0.4567,0.3481]} <0x2febc680> 06 01/02/15 10:33:20.125 Device_Variable::m_szValue_set device: 47 service: urn:intvelt-com:serviceId:HueColors1 variable: CurrentPreset was: 1 now: 1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2febc680> 50 01/02/15 10:33:20.452 luup_log:26: Philips Hue Controller: Got JSON on get username: {"state": {"on":true,"bri":254,"hue":57359,"sat":78,"xy":[0.4567,0.3481],"alert":"none","effect":"none","colormode":"xy","reachable":true}, "type": "Color light", "name": "Undercabinet", "modelid": "LST001", "swversion": "66010400", "pointsymbol": { "1":"none", "2":"none", "3":"none", "4":"none", "5":"none", "6":"none", "7":"none", "8":"none" }} <0x2febc680> 50 01/02/15 10:33:20.453 luup_log:26: Philips Hue Controller: Response received for light state <0x2febc680> 06 01/02/15 10:33:20.453 Device_Variable::m_szValue_set device: 26 service: urn:intvelt-com:serviceId:HueController1 variable: LinkStatus was: Hue hub is up and linked now: Hue hub is up and linked #hooks: 0 upnp: 0 v:0xfcc330/NONE duplicate:1 <0x2febc680> 50 01/02/15 10:33:20.453 luup_log:26: Philips Hue Controller: Updating for light <0x2febc680> 06 01/02/15 10:33:20.454 Device_Variable::m_szValue_set device: 47 service: urn:intvelt-com:serviceId:HueColors1 variable: ColorTemperature was: 0 now: 0 #hooks: 0 upnp: 0 v:0xff9438/NONE duplicate:1 <0x2febc680>

I am a little unclear on which device is which, and your setup.

Vera device 71 = Insteon KPL with ID 2B.A7.14
Vera device 46 = Philips Hue light that you are controlling

It looks like you have a scene #28 (“Undercabinet Lights On”) which is triggered by turning “2B.A7.14 button 1” on.
This scene then turns device #46 (Philips Hue) on.

It looks like you have a scene #29 (“Undercabinet Lights Off”) which is triggered by turning “2B.A7.14 button 1” off.
This scene then turns device #46 (Philips Hue) off.

The issue only happens when you run from the switch, correct? Evert time you do it from the Vera dashboard, it works exactly as intended?

Yep, I believe that is all exactly correct. It does not seem that triggering the scenes (Undercabinet light on or off) from the dashboard causes the same behavior.