insteonPLM not registering fast ON/OFF

johnofcamas · January 19, 2017, 11:18pm

I have followed the instructions pretty faithfully for registering a switch as both a standard item, and a ‘fastonoff’ item, but the fastonoff item does not seem to trigger when I double tap on the switch.

Here is the .items

Switch OfficeLight "Office Light" <light> (office) [ "Lighting" ] {insteonplm="1B.41.E8:F00.00.02#switch"}
Switch OfficeLightFastOnOff "Office Light (fast on/off)" <light> {insteonplm="1B.41.E8:F00.00.02#fastonoff"}

I see the following from the logs:
(openhab.log)

2017-01-19 15:13:55.173 [INFO ] [onplm.internal.device.MessageHandler] - LightOnSwitchHandler: device 1B.41.E8 was switched on FAST.
2017-01-19 15:13:55.173 [INFO ] [onplm.internal.device.MessageHandler] - LightOnSwitchHandler: device 1B.41.E8 was switched on FAST.

and from events.log

2017-01-19 15:13:55.174 [ItemStateChangedEvent     ] - OfficeLight changed from OFF to ON

ranielsen · January 20, 2017, 1:05am

I’m using OH1 and i have the folowing:

.items file:

Dimmer bStairsLights2       "Basement Stairs Light 2"             {insteonplm="23.9F.AD:F00.00.11#dimmer,related=22.F8.74"}
Switch bStairsLights2Fast   "Basement Stairs Light 2 Fast On/Off" {insteonplm="23.9F.AD:F00.00.11#fastonoff,related=22.F8.74"}

openhab.log:

2017-01-19 18:47:48.147 [INFO ] [.o.b.i.i.device.MessageHandler] - LightOffSwitchHandler: device 23.9F.AD was switched off FAST.
2017-01-19 18:47:48.151 [INFO ] [.o.b.i.i.device.MessageHandler] - LightOffDimmerHandler: device 23.9F.AD was turned off FAST.

events.log

2017-01-19 18:47:48 - bStairsLights2Fast state updated to OFF
2017-01-19 18:47:48 - bStairsLights2 state updated to OFF

It looks like you are using OH2, the little I played around with OH2, it appears it doesn’t send duplicate events. What happens if you trigger a fast off then try a fast on?

johnofcamas · January 20, 2017, 1:12am

Yes, I’m using OH2
It’s a bit erratic, but the most common scenario when I ‘fast off’ then ‘fast on’ is:

2017-01-19 17:10:22.199 [INFO ] [onplm.internal.device.MessageHandler] - LightOffSwitchHandler: device 1B.41.E8 was switched off FAST.
2017-01-19 17:10:22.199 [INFO ] [onplm.internal.device.MessageHandler] - LightOffSwitchHandler: device 1B.41.E8 was switched off FAST.

2017-01-19 17:10:22.200 [ItemStateChangedEvent     ] - OfficeLightFastOnOff changed from ON to OFF

Oddly, when I double tap ‘on’, it was never logged

ranielsen · January 20, 2017, 1:18am

This looks like some sort of different behavior between OH1 and OH2. If you enabled debug logging of InsteonPLM, this would give more detailed info on what the binding is doing. I have no idea on how to enable debugging with OH2.

johnofcamas · January 20, 2017, 1:25am

How can I enable logging in insteonPLM?

ranielsen · January 20, 2017, 1:30am

The instructions for OH1 are at https://github.com/openhab/openhab1-addons/wiki/Insteon-PLM-Binding#trouble-shooting

Logging works differently with OH2.

rlkoshak · January 20, 2017, 5:12pm

See

and

http://docs.openhab.org/administration/logging.html

johnofcamas · January 21, 2017, 12:39am

OK, I’ve turned on logging… and WOW is it verbose. Please advise if there is something I should be looking for (wrt FASTON)

Here is the log timestamped from when I hit a double tap on a switch:

2017-01-20 16:38:15 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x12|command2:0x00|
2017-01-20 16:38:15 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x12|command2:0x00|
2017-01-20 16:38:15 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-01-20 16:38:15 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 1B.41.E8:FastOnOff->LightOnSwitchHandler cmd1:0x12 group 1/-1:IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x12|command2:0x00|
2017-01-20 16:38:15 org.openhab.binding.insteonplm.internal.device.MessageHandler$LightOnSwitchHandler.handleMessage(MessageHandler.java:406) - LightOnSwitchHandler: device 1B.41.E8 was switched on FAST.
2017-01-20 16:38:15 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 1B.41.E8:FastOnOff publishing: ON
2017-01-20 16:38:15 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x12|command2:0x00|
2017-01-20 16:38:15 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-01-20 16:38:15 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 1B.41.E8:GenericSwitch->LightOnSwitchHandler cmd1:0x12 group 1/1:IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x12|command2:0x00|
2017-01-20 16:38:15 org.openhab.binding.insteonplm.internal.device.MessageHandler$LightOnSwitchHandler.handleMessage(MessageHandler.java:406) - LightOnSwitchHandler: device 1B.41.E8 was switched on FAST.
2017-01-20 16:38:15 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 1B.41.E8:GenericSwitch publishing: ON
2017-01-20 16:38:15 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 1B.41.E8:GenericLastTime publishing: 2017-01-20T16:38:15

And, here is the complete ‘events’ log:

2017-01-20 16:38:15.941 [InsteonPLMActiveBinding   ] - got msg: IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x12|command2:0x00|
2017-01-20 16:38:15.942 [MessageDispatcher         ] - all link message: IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x12|command2:0x00|
2017-01-20 16:38:15.942 [MessageDispatcher         ] - all link message is no duplicate: true/true
2017-01-20 16:38:15.942 [MessageDispatcher         ] - 1B.41.E8:FastOnOff->LightOnSwitchHandler cmd1:0x12 group 1/-1:IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x12|command2:0x00|
2017-01-20 16:38:15.942 [MessageHandler            ] - LightOnSwitchHandler: device 1B.41.E8 was switched on FAST.
2017-01-20 16:38:15.942 [DeviceFeature             ] - 1B.41.E8:FastOnOff publishing: ON
2017-01-20 16:38:15.942 [MessageDispatcher         ] - all link message: IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x12|command2:0x00|
2017-01-20 16:38:15.942 [MessageDispatcher         ] - all link message is no duplicate: true/true
2017-01-20 16:38:15.942 [MessageDispatcher         ] - 1B.41.E8:GenericSwitch->LightOnSwitchHandler cmd1:0x12 group 1/1:IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x12|command2:0x00|
2017-01-20 16:38:15.943 [MessageHandler            ] - LightOnSwitchHandler: device 1B.41.E8 was switched on FAST.
2017-01-20 16:38:15.943 [DeviceFeature             ] - 1B.41.E8:GenericSwitch publishing: ON
2017-01-20 16:38:15.943 [DeviceFeature             ] - 1B.41.E8:GenericLastTime publishing: 2017-01-20T16:38:15
2017-01-20 16:38:16.142 [InsteonPLMActiveBinding   ] - got msg: IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:0F.9D.D9|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x12|command2:0x01|
2017-01-20 16:38:16.143 [MessageDispatcher         ] - all link message: IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:0F.9D.D9|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x12|command2:0x01|
2017-01-20 16:38:16.143 [MessageDispatcher         ] - all link message: IN:Cmd:0x50|fromAddress:1B.41.E8|toAddress:0F.9D.D9|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x12|command2:0x01|
2017-01-20 16:38:16.143 [DeviceFeature             ] - 1B.41.E8:GenericLastTime publishing: 2017-01-20T16:38:16

johnofcamas · January 21, 2017, 2:07am

I think I’m making some progress, the problem was my rule file…!!!

I had this:

rule "OfficeFastOn"
when
	Item OfficeLightFastOnOff received command ON
then
    logDebug("rulelog", "Office Light FASTON")
end

When it should have been this:

rule "OfficeFastOn"
when
	Item OfficeLightFastOnOff received update ON
then
    logDebug("rulelog", "Office Light FASTON")
end

update, instead of command! Now, it’s not the most reliable atm, but I think that might have to do more with insteon strangeness, than anything else.

ranielsen · January 21, 2017, 2:15pm

Every time you see:

2017-01-20 16:38:15.942 [MessageHandler            ] - LightOnSwitchHandler: device 1B.41.E8 was switched on FAST.
2017-01-20 16:38:15.942 [DeviceFeature             ] - 1B.41.E8:FastOnOff publishing: ON

You should see a corresponding event indicating the item OfficeLightFastOnOff is ON. At least that’s how it works with OH1. Maybe you also need to force the state back to OFF in you rule:

    OfficeLightFastOnOff.postUpdate(OFF)