Insteon open/close sensor misses events

Bernd,

I’m using the old (2012) hub. I always have debugging on (too much tinkering I guess). Have fooled around with Houselinc, but don’t really have any documentation to work out what the options here are.

Looking at the log, I see events when the sensor closes, and events when it opens, but much of it is ALL_LINK_CLEANUP and so on. For instance, here is a snip of the log, filtered for my door sensor. I close the sensor (detected), then wait a second or so, then open it. There is activity when I open the sensor, but OPEN is not published. Here it is:

2015-11-30 13:35:06 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 13:35:06 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 13:35:06 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 13:35:06 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:GenericLastTime publishing: 2015-11-30T13:35:06
2015-11-30 13:35:07 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|command2:0x01|
2015-11-30 13:35:07 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|command2:0x01|
2015-11-30 13:35:07 DEBUG o.o.b.i.i.d.MessageDispatcher[:72]- 32.8C.35:HiddenDoorSensorData->NoOpMsgHandler cmd1:0x13 group 1/1:IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|command2:0x01|
2015-11-30 13:35:07 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|command2:0x01|
2015-11-30 13:35:07 DEBUG o.o.b.i.i.d.MessageDispatcher[:72]- 32.8C.35:WirelessMotionSensorContact->ClosedSleepingContactHandler cmd1:0x13 group 1/1:IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|command2:0x01|
2015-11-30 13:35:07 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:WirelessMotionSensorContact publishing: CLOSED
2015-11-30 13:35:07 DEBUG o.o.b.i.i.device.InsteonDevice[:370]- still waiting for query reply from 32.8C.35 for another 805 usec
2015-11-30 13:35:07 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:GenericLastTime publishing: 2015-11-30T13:35:07
2015-11-30 13:35:07 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|command2:0x01|
2015-11-30 13:35:07 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|command2:0x01|
2015-11-30 13:35:07 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|command2:0x01|
2015-11-30 13:35:07 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:GenericLastTime publishing: 2015-11-30T13:35:07
2015-11-30 13:35:07 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x13|command2:0x01|
2015-11-30 13:35:07 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x13|command2:0x01|
2015-11-30 13:35:07 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x13|command2:0x01|
2015-11-30 13:35:07 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:GenericLastTime publishing: 2015-11-30T13:35:07
2015-11-30 13:35:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x46=ALL_LINK_CLEANUP:2:1|command1:0x13|command2:0x01|
2015-11-30 13:35:08 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x46=ALL_LINK_CLEANUP:2:1|command1:0x13|command2:0x01|
2015-11-30 13:35:08 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x46=ALL_LINK_CLEANUP:2:1|command1:0x13|command2:0x01|
2015-11-30 13:35:08 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:GenericLastTime publishing: 2015-11-30T13:35:08
2015-11-30 13:35:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:13.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|
2015-11-30 13:35:08 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:13.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|
2015-11-30 13:35:08 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:13.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|
2015-11-30 13:35:08 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:GenericLastTime publishing: 2015-11-30T13:35:08
2015-11-30 13:35:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:13.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|
2015-11-30 13:35:08 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:13.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|
2015-11-30 13:35:08 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:13.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|
2015-11-30 13:35:08 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:GenericLastTime publishing: 2015-11-30T13:35:08
2015-11-30 13:35:09 DEBUG o.o.b.i.i.device.InsteonDevice[:374]- gave up waiting for query reply from device 32.8C.35
2015-11-30 13:35:09 DEBUG o.o.b.i.i.device.InsteonDevice[:379]- qe taken off direct: WirelessMotionSensorContact(1:1:5) OUT:Cmd:0x62|toAddress:32.8C.35|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x00|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xD2|
2015-11-30 13:35:11 DEBUG o.o.b.i.i.d.RequestQueueManager[:132]- device queue for 32.8C.35 is empty!
2015-11-30 13:35:17 DEBUG o.o.b.i.internal.driver.Port[:382]- writing (500): OUT:Cmd:0x62|toAddress:32.8C.35|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x00|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xD2|
2015-11-30 13:35:17 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x47=ALL_LINK_CLEANUP:3:1|command1:0x11|command2:0x01|
2015-11-30 13:35:17 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x47=ALL_LINK_CLEANUP:3:1|command1:0x11|command2:0x01|
2015-11-30 13:35:17 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x47=ALL_LINK_CLEANUP:3:1|command1:0x11|command2:0x01|
2015-11-30 13:35:17 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:GenericLastTime publishing: 2015-11-30T13:35:17
2015-11-30 13:35:18 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x2B=ACK_OF_DIRECT:3:2|command1:0x2E|command2:0x00|
2015-11-30 13:35:18 DEBUG o.o.b.i.i.d.MessageDispatcher[:134]- 32.8C.35:WirelessMotionSensorContact DIRECT_ACK: q:QUERY_PENDING cmd: 80
2015-11-30 13:35:18 DEBUG o.o.b.i.i.d.MessageDispatcher[:139]- changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x2B=ACK_OF_DIRECT:3:2|command1:0x2E|command2:0x00|
2015-11-30 13:35:18 DEBUG o.o.b.i.i.d.MessageDispatcher[:159]- defdisp: 32.8C.35:WirelessMotionSensorContact set status to: QUERY_ANSWERED
2015-11-30 13:35:18 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:GenericLastTime publishing: 2015-11-30T13:35:18
2015-11-30 13:35:19 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x51|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x17=DIRECT:3:1|command1:0x2E|command2:0x00|userData1:0x01|userData2:0x01|userData3:0x3D|userData4:0x57|userData5:0x00|userData6:0x40|userData7:0x40|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xD2|
2015-11-30 13:35:19 DEBUG o.o.b.i.i.d.MessageHandler[:607]- HiddenDoorSensorDataReplyHandler: 32.8C.35 got light level: 64, battery level: 87
2015-11-30 13:35:19 DEBUG o.o.b.i.i.device.DeviceFeature[:249]- 32.8C.35:HiddenDoorSensorData publishing: 64
2015-11-30 13:35:19 DEBUG o.o.b.i.i.device.DeviceFeature[:249]- 32.8C.35:HiddenDoorSensorData publishing: 87
2015-11-30 13:35:19 DEBUG o.o.b.i.i.d.MessageDispatcher[:151]- 32.8C.35:WirelessMotionSensorContact->NoOpMsgHandler DIRECT
2015-11-30 13:35:19 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:GenericLastTime publishing: 2015-11-30T13:35:19
2015-11-30 13:35:20 DEBUG o.o.b.i.internal.driver.Port[:382]- writing (500): OUT:Cmd:0x62|toAddress:32.8C.35|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x00|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xD2|

I close the sensor at 13:35:06, at 13:35:07 CLOSE is published. I then open the sensor at (or about) 13:35:17 (10 seconds later - so some time), there is a flurry of activity, last heard from is updated etc. but no OPEN published. This is repeatable. Not sure what is going on. I will investigate further with different Houselinc settings.

Regards,

Bernd,

After much experimenting, here are my results:

The reliability of the sensor degrades with speed of switching. The data comes into the binding, but is lost somewhere in processing.

I got the best results with “data” (ie battery etc) disables and “GenericLastTime” removed (this published a lot). I also switched to using two groups. I was able to get this to work by switching the contact type to the LeakSensorContact type, as this seems to be how this works.

My additional devices file looks like this:

  <device productKey="F00.00.03">
     <model>2845-222</model>
     <description>Hidden Door Sensor</description>
     <feature name="contact">LeakSensorContact</feature>
 </device>

Full log is here: My Dropbox link

Here is a filtered list showing incoming messages and published data, with starting out slow, then speeding up OPEN/CLOSE presses.

2015-11-30 16:29:41 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:29:42 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:29:42 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:29:48 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:29:49 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:29:52 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:29:54 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:29:58 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:29:58 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:29:59 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:00 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:03 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:03 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:04 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x11|command2:0x02|
2015-11-30 16:30:05 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:07 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:07 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:09 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:09 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:12 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:12 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:13 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:14 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:17 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:18 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:18 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:22 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:22 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:23 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:24 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:26 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:27 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:27 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:28 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:31 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:31 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:32 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:33 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:35 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:36 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:37 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:39 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:39 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:42 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:43 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:43 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:45 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:46 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x11|command2:0x02|
2015-11-30 16:30:46 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:48 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:49 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:49 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:50 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:51 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:52 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:53 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:55 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:56 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:56 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:58 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:59 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:01 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:01 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x11|command2:0x02|
2015-11-30 16:31:01 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:03 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:03 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:04 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x11|command2:0x02|
2015-11-30 16:31:04 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:05 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:06 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:06 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:09 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:10 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:10 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:10 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x11|command2:0x02|
2015-11-30 16:31:11 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:12 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:13 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:13 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x11|command2:0x02|
2015-11-30 16:31:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:17 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:17 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:19 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:19 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:20 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x11|command2:0x02|
2015-11-30 16:31:20 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:21 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:22 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:22 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x11|command2:0x02|
2015-11-30 16:31:22 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:23 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:24 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:24 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:26 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:26 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x11|command2:0x02|
2015-11-30 16:31:27 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:28 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:28 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:29 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:30 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:30 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:31 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:32 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:35 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:35 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:38 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x11|command2:0x01|
2015-11-30 16:31:38 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x11|command2:0x02|
2015-11-30 16:31:40 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:40 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:42 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:43 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:43 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:31:45 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:31:46 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|

Published Data:

2015-11-30 16:29:41 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:29:42 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:29:48 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:29:52 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:29:54 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:29:58 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:29:59 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:03 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:30:04 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:07 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:30:09 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:12 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:30:13 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:16 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:30:18 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:22 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:30:23 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:26 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:30:27 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:31 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:30:32 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:35 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:30:36 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:39 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:30:43 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:46 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:49 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:53 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:55 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:30:56 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:58 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:01 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:31:01 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:04 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:06 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:08 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:10 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:13 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:16 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:17 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:20 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:24 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:26 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:28 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:31 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:38 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: OPEN
2015-11-30 16:31:38 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:40 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:31:43 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED

As you can see it gets worse as you get faster.

Any thoughts?

Traveling, can’t look at it until the weekend…

No prob, I’ll have a dig around tomorrow, maybe with trace on, see how the state machine progresses.

It seems to miss the OPEN (no is-not-duplicate message).

I’ll let you know if I find something.

Regards,

Nick Waterton P.Eng
Sent from my iPhone

Bernd,

I think I found it.

What happens is that the ALL_LINK_BROADCAST comes in correctly, and is detected. State machine is now waiting for an ALL_LINK_CLEANUP - treats everything else as a duplicate. However, if you activate the sensor quickly enough, the next ALL_LINK_BROADCAST comes in (with a different state - either group or cmd1 depending on how the sensor is configured) before any ALL_LINK_CLEANUP (which may never arrive) and is treated as a duplicate - even though it has a different state in cmd1. Thus the transition is lost.

So the solution is either - modify the state machine, so that an ALL_LINK_BROADCAST with a different state is treated as a missed CLEAN - SUCCESS step, or customize the contact handler somehow.

This may be more of a general issue for fast transitions that come in before a CLEAN. I guess normally you don’t get transitions this fast, so the issue is not evident. But our front door can open and close in a fraction of a second. The Insteon system seems fast enough to detect it, but it’s short cycling the state machine.

I’ll see if I can come up with a fix that doesn’t break everything else…

Regards,

The cleanup is only sent to devices that the sensor knows about. Make sure
it’s linked as a controller of the hub, and that the hub has the sensor as
a responder. Check the link databases using insteon terminal. I had very
similar behavior when entries were missing in either plm or the devices
linkdb.

Bernd,

Well I have spent some time on this. The Sensor is linked to the Hub, but I don’t know if the Hub is linked to the sensor (can the sensor even be a responder?). Haven’t had much luck getting insteon terminal up and running (another project I suppose). OK you can link the sensor as a responder - just did it. Makes no difference though.

Having dug into it, the hidden door sensor is more like the leak detector than the other (external) door sensor (it has exactly the same commands and responses as the leak detector).

The main thing that seems to be slowing down the response (other than the state machine stuff) is the battery check. This seems to take 2-3 seconds to get a response - if it does, mostly it doesn’t. During that time, transitions are handled by a NoOp handler, which ignores broadcast messages.

So I have changed the device_type and device_features to use the leak detector configuration, and changed the OpenedOrClosedContactHandler to handle both the leak detector and the hidden door sensor (as the messages are identical). I moved theHiddenDoorSensorDataReplyHandler to the contact feature, to avoid the data feature ignoring valid transitions (may be another way of doing this?) .

The hidden door sensor also has an option to enable repeat OPEN or CLOSE - which sends the current state every 5 minutes (probably chews through the battery - but it gives you a datum point). I moved the battery check to this feature, and added the heartbeat detector (which also does a battery check). You can select the heartbeat frequency from 5 minutes to 24 hours (which also updates OPEN/CLOSE status) independent of repeat OPEN/CLOSE.

Interestingly the leak detector also has these features, but no user interface (in Houselinc) heartbeat is set at 24 hours, and groups as 2 - the hidden door sensor allows you to configure these.

I don’t know if the GenericLastTime feature slows things down, but it muddies the logs, so I turned it off for a while.

It’s better this way, but still misses events (although they eventually get corrected after 5 minutes). The state machine still misses things. If you get a broadcast, no clean_up and another broadcast, it ignores it. If you get a broadcast, clean_up but then miss the next broadcast, then get a clean_up, it is ignored (because it assumes is’s a duplicate clean_up).

There is an option to enable/disable clean_up reports in the sensor configuration, I have this turned off (as it didn’t seem to do anything) - I assume this is just sending a report of which devices didn’t reply or something - is this of any use?

I’ll keep fiddling.

You definitely want the cleanup messages. They are necessary to make the
state machine work. Are you getting any cleanup messages at all? Are they
only missing when you trigger the sensor rapid fire?

Found time to look at your log.

  1. You are getting the broadcast and the cleanup reports which is good, so forget about my question in my last post.

  2. I see no “broadcast success reports” in your log. Those are broadcasts with cmd1=0x06. The state machine expects them. The insteon developer notes also mention that it should send out the broadcast success reports. Why does your sensor not sent them? Anybody out there who has the same sensor and also doesn’t get the cmd1=0x06 broadcasts? Alternatively: want to try re-linking the sensor and hope the “Success” broadcasts come in then?

  3. In the below situation I don’t understand why the state machine does not work correctly at 16:30:45, when this message comes in:

    2015-11-30 16:30:45 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
    2015-11-30 16:30:45 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|

Why is this message ignored by the state machine? You mentioned something that while the battery status is queried, broadcasts go to a NoOp handler. That was certainly not intentional. Can you insert more debug logging into the code to find out what’s going on? And when you do the tests, would you remind reverting to the original device definition so it’s easier for me to follow what’s going on?

Here some more lines from the section of the log that I don’t understand.

2015-11-30 16:30:43 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:43 DEBUG o.o.b.i.i.d.MessageDispatcher[:72]- 32.8C.35:LeakSensorContact->OpenedOrClosedContactHandler cmd1:0x11 group 2/-1:IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x02|
2015-11-30 16:30:43 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED
2015-11-30 16:30:44 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x02|
2015-11-30 16:30:44 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x02|
2015-11-30 16:30:45 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:45 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-11-30 16:30:46 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x11|command2:0x02|
2015-11-30 16:30:46 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x11|command2:0x02|
2015-11-30 16:30:46 DEBUG o.o.b.i.i.d.MessageDispatcher[:72]- 32.8C.35:LeakSensorContact->OpenedOrClosedContactHandler cmd1:0x11 group 2/-1:IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.02|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x11|command2:0x02|
2015-11-30 16:30:46 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:LeakSensorContact publishing: CLOSED

And about the insteon terminal: please let me know what problems you hit
even if they seem very simple. I really want to make this tool easy to use.

Bernd,

About Insteon Terminal, I’m not sure if I have to re-enter all my insteon devices in the configuration file, or just the modem? (and it gets the list from the modem). So I’m sort of stuck there.

Anyway - open/close sensor.

I do get “Success” broadcasts, if you wait long enough for them to come through. Takes about 3-6 seconds for them to show up.

The messages you list are ignored because the state machine thinks they are duplicate broadcasts.

The thing I was having a problem with is how the StateMachine is instantiated, it looks as if there is a new instance for each contact handler (not each device). Is this the case?

What I see is that an OPEN is treated separately from a CLOSE (as far as the State Machine is concerned). So if you open and close slowly (say 2 seconds), there is time for the ALL_LINK_CLEANUP to arrive and reset the StateMachine. However, if you open and close faster, then the next ALL_LINK_BROADCAST arrives before the CLEANUP, and is treated as a duplicate - even though it is for a different state.

Perhaps I’m not being too clear here (I am confusing myself). This is what you get on a plain vanilla 1.8 binding (no changes) if you wait long enough:

2015-12-03 15:40:17 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x13|command2:0x01|
2015-12-03 15:40:20 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x43=ALL_LINK_CLEANUP:3:0|command1:0x13|command2:0x01|
2015-12-03 15:40:20 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x47=ALL_LINK_CLEANUP:3:1|command1:0x13|command2:0x01|
2015-12-03 15:40:29 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x11|command2:0x01|
2015-12-03 15:40:34 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x4B=ALL_LINK_CLEANUP:3:2|command1:0x11|command2:0x01|
2015-12-03 15:40:34 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x01|
2015-12-03 15:40:35 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:11.02.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|

0x13 is the close, 0x11 is the open. I’m missing the “Success” on the close, but get it on the open - 6 seconds later.

Here’s what happens if you open/close faster:

2015-12-03 16:01:59 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x13|command2:0x01|
2015-12-03 16:02:02 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x13|command2:0x01|
2015-12-03 16:02:05 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x42=ALL_LINK_CLEANUP:2:0|command1:0x13|command2:0x01|
2015-12-03 16:02:06 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-12-03 16:02:06 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x01|
2015-12-03 16:02:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x11|command2:0x01|
2015-12-03 16:02:11 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x42=ALL_LINK_CLEANUP:2:0|command1:0x13|command2:0x01|
2015-12-03 16:02:11 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2015-12-03 16:02:11 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x01|
2015-12-03 16:02:12 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x46=ALL_LINK_CLEANUP:2:1|command1:0x11|command2:0x01|
2015-12-03 16:02:12 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x01|
2015-12-03 16:02:12 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x13|command2:0x01|
2015-12-03 16:02:13 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|command2:0x01|
2015-12-03 16:02:15 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x4B=ALL_LINK_CLEANUP:3:2|command1:0x11|command2:0x01|
2015-12-03 16:02:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x01|
2015-12-03 16:02:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:11.02.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|
2015-12-03 16:02:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:11.02.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|

and here is the open/closed display:

2015-12-03 16:01:59 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:WirelessMotionSensorContact publishing: CLOSED
2015-12-03 16:02:08 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:WirelessMotionSensorContact publishing: OPEN
2015-12-03 16:02:12 DEBUG o.o.b.i.i.device.DeviceFeature[:263]- 32.8C.35:WirelessMotionSensorContact publishing: CLOSED

This is opening and closing about 5 times, with ~1 second between each - starting with a close, and ending with an open. You can see the device is left in the incorrect state (says CLOSED but is actually OPEN)

The new broadcast messages are ignored, because they arrive before Success messages, while the State Machine is expecting a CLEAN. And because there is a separate state machine for each contact, a CLEAN for CLOSE does not advance the machine for OPEN. So just because you got a CLEAN for the close, the OPEN is ignored if it came in before the CLEAN for the previous OPEN. Does this make it clearer? I think I need a diagram…

Anyway, the sensor report gets stuck in OPEN or CLOSE, when the actual device is in the opposite state, this happens if you activate it faster than the CLEAN/SUCCESS messages come in (about 3 seconds, as you can miss one of these). They sort of overlap each other.

I’m not sure if I’m right about the battery check slowing things down, it does confuse the logs.

With my new contact handler, it does work faster ~ 2 seconds works, but the separate state machines for each contact is still a problem (unless I’m wrong on how this is instantiated).

Is the CLEAN broadcast supposed to be for the device or the command (or the group)? I’m not sure, ie if you close, then open, do you get a separate CLEAN broadcast for both the 0x13 and 0x11 commands, or just one to cover the last command (0x11) ie for the whole device?

The log of this last sequence is uploaded to dropbox (overwriting the last log).

Let me know if my logic is correct, or am I confusing myself.

Regards,

Below is an analysis of the log.

There is one state machine per feature, message handler, and group. Since there is a different message handler for 0x11 and 0x13 you are correct that there are two different state machines at work, one for close, one for open messages (I had forgotten about that, had to relearn it from the code).

Looking at the log, I must say there are at times severe message losses. In one case nothing but a single CLEANUP message arrives.

Originally I introduced the state machine because @ranielsen didn’t like all the duplicates being posted (and neither did I). If you don’t care about weeding out the duplicates, you can introduce a new feature with a new message handler that does not weed out duplicates, but overrides the isDuplicate() method to always return false, and drops the SUCCESS messages altogether (install noop handler for cmd1=0x06). Actually the cleaner way would be to introduce another parameter for the base class message handler to honor a configuration flag “eliminate_duplicates=false” (which defaults to “true”), and then in device_features.xml just set “eliminate_duplicates=true” for the relevant handlers of the new feature you introduced (maybe call that one WirelessMotionSensorContactWithDuplicates).

This will not be a panacea though. You realize that sometimes there are late cleanup messages coming in that will say “CLOSED”, overriding a correct “OPEN” broadcast that actually was sent later. I would imagine it’ll work more reliably, but never 100%.

A) sensor closed:
----------------
1)  2015-12-03 16:01:59 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x13|command2:0x01|
SHOULD PUBLISH "CLOSED" HERE (observed, works)
2)  2015-12-03 16:02:02 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x13|command2:0x01|
2d) 2015-12-03 16:02:05 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x42=ALL_LINK_CLEANUP:2:0|command1:0x13|command2:0x01|
3)  MISSING SUCESS MESSAGE!


B) sensor opened:
----------------
1)  2015-12-03 16:02:06 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
NOT PUBLISHING HERE (because of state machine being screwed up)
2)  2015-12-03 16:02:06 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x01|
(THIS BRINGS STATE MACHINE INTO SANE STATE)
1d) 2015-12-03 16:02:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x11|command2:0x01|
THIS IS A LATE DUPLICATE of 1), SHOULD PUBLISH HERE (observed, works). BUT NOW THE STATE MACHINE IS SCREWED UP BECAUSE IT LOST THE "CLEANUP".
3)  MISSING SUCCESS MESSAGE

C) sensor closed:
----------------
1)  MISSING BROADCAST!
2)  2015-12-03 16:02:11 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x42=ALL_LINK_CLEANUP:2:0|command1:0x13|command2:0x01|
(WEEDED OUT AS DUPLICATE CLEANUP, BUT IT's NOT)
3)  MISSING CLEANUP!
4)  MISSING SUCCESS!

D) sensor opened:
----------------
1)  2015-12-03 16:02:11 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
WEEDED OUT AS DUPLICATE BECAUSE STATE MACHINE WAS EXPECTING CLEANUP
2)  2015-12-03 16:02:11 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x01|
2d) 2015-12-03 16:02:12 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x46=ALL_LINK_CLEANUP:2:1|command1:0x11|command2:0x01|
2d) 2015-12-03 16:02:12 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x01|
3)  MISSING SUCCESS!

E) sensor closed:
----------------
1)  2015-12-03 16:02:12 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x13|command2:0x01|
SHOULD PUBLISH "CLOSED" HERE (happening, this is correct!)
1d) 2015-12-03 16:02:13 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|command2:0x01|
2) MISSING CLEANUP!
3) MISSING SUCCESS!

F) sensor opened:
----------------
1) MISSING BROADCAST!
2)  2015-12-03 16:02:15 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x4B=ALL_LINK_CLEANUP:3:2|command1:0x11|command2:0x01|
2d) 2015-12-03 16:02:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:2A.E7.67|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x11|command2:0x01|
3)  2015-12-03 16:02:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:11.02.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|
3d) 2015-12-03 16:02:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x50|fromAddress:32.8C.35|toAddress:11.02.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00|

Thanks for the analysis, Bernd,

I did play around with allowing duplicates (not quite as you suggested, but similar). It was ugly, and as you say still didn’t work 100%.

I have come to the conclusion that the hidden door sensor will never be 100% reliable, and as such, should not be used wherever you need a reliable open/close indication (such as security). The same goes for the wireless open/close sensor, which has a similar problem.

They do work fine in situations where the open/close does not occur quickly, such as windows and sliding doors. The insteon network also works reliably (turning on/off lights etc).

The hidden door sensor has one very useful feature however, the ability to change the heartbeat timing, and enable repeat of open/close (every 5 minutes). The wireless open/close sensor also has the repeat open/close feature, but it’s much more difficult to enable as it’s not exposed in Houselinc.

What I have done is to install an Aeon Z-Wave hidden door sensor (which is 100% reliable), along with the insteon sensor. I now use the insteon sensor to initialize the Aeon Z-Wave sensor. The Z-Wave sensor is now the primary door status sensor (with insteon as backup).

So on openHAB startup, both sensors are Unintialised, but within 5 minutes, the insteon sensor repeats it’s status, which I then use to initialize the Z-Wave sensor status. It remains to be seen how this will impact the battery life of the insteon sensor.

I have also changed my closet door sensor to repeat it’s status every 15 minutes, so it gets initialized also (eventually).

In order for this to work, I had to modify the OpenedOrClosedContactHandler in MessageHandler, as the repeat messages and Heartbeat are sent to group 4 (contact status was being ignored in group 4 previously).

The new OpenedOrClosedContactHandler should work for single or dual group messages, for Leak Detector, Wireless open/close Sensor and the Hidden Door sensor. it also detects heartbeat, and requests battery status (only on repeat and heatbeat, not normal open/close actions). Battery status only works on the hidden door sensor (no battery state reported by the other sensors). It also traps “low battery” triggers sent to group 3. The feature is #contact, field=low_battery and is a decimal type == 1.

This is the new contact handler:

public static class OpenedOrClosedContactHandler extends MessageHandler {
		OpenedOrClosedContactHandler(DeviceFeature p) { super(p); }
		@Override
		public void handleMessage(int group, byte cmd1, Msg msg,
				DeviceFeature f, String fromPort) {
			try {
				byte cmd2 = msg.getByte("command2");
				switch (cmd1) {
				case 0x11:
					switch (cmd2) {
					case 0x02:
						m_feature.publish(OpenClosedType.CLOSED, StateChangeType.ALWAYS);  //for two groups reporting
						break;
					case 0x01:
                        m_feature.publish(OpenClosedType.OPEN, StateChangeType.ALWAYS);  //for single or dual group reporting
						break;
                    case 0x03:
                        m_feature.publish(new DecimalType(1), StateChangeType.ALWAYS, "field", "low_battery"); // low battery message
					case 0x04:
                        sendExtendedQuery(f, (byte)0x2e, (byte) 00);  //query battery state
						m_feature.publish(OpenClosedType.OPEN, StateChangeType.ALWAYS);  //periodic update (if repeat open selected)
						break;
					default: // do nothing
						break;
					}
					break;
				case 0x13:
					switch (cmd2) {
                    case 0x01:
                        m_feature.publish(OpenClosedType.CLOSED, StateChangeType.ALWAYS);  //if set to single group
						break;
                    case 0x03:
                        m_feature.publish(new DecimalType(1), StateChangeType.ALWAYS, "field", "low_battery"); // low battery message
					case 0x04:
                        sendExtendedQuery(f, (byte)0x2e, (byte) 00);  //query battery state
						m_feature.publish(OpenClosedType.CLOSED, StateChangeType.ALWAYS);  //periodic update (if repeat closed selected)
						break;
					default: // do nothing
						break;
					}
					break;
				}
			} catch (FieldException e) {
				logger.debug("{} no cmd2 found, dropping msg {}", nm(), msg);
				return;
			}
		}
	}

It has been working fine for the last few days, but I haven’t done extended testing so far. my sensors, (Leak, open/close, hidden door) have been reporting correctly using this contact handler, but this is only a few days worth of data.

The new device I created is:

 <device productKey="F00.00.03">
     <model>2845-222</model>
     <description>Hidden Door Sensor</description>
     <feature name="contact">TestHiddenDoorSensorContact</feature>
     <feature name="data">HiddenDoorSensorData</feature>
     <feature name="lastheardfrom">GenericLastTime</feature>
 </device>

And the feature is:

<feature name="TestHiddenDoorSensorContact">
	<message-dispatcher>DefaultDispatcher</message-dispatcher>
	<message-handler cmd="0x03">NoOpMsgHandler</message-handler>
	<message-handler cmd="0x11">OpenedOrClosedContactHandler</message-handler>
	<message-handler cmd="0x13">OpenedOrClosedContactHandler</message-handler>
	<message-handler cmd="0x19">NoOpMsgHandler</message-handler>
	<message-handler cmd="0x2e">NoOpMsgHandler</message-handler>
	<command-handler command="OnOffType">NoOpCommandHandler</command-handler>
	<poll-handler>NoPollHandler</poll-handler>
</feature>

In my more_devices.xml and more_features.xml files.

I think it would be worth updating the contact handler, as it should really have been trapping the contact status in group 4 (previously it was just updating the lastheardfrom date/time). I changed the StateChangeType from CHANGED to ALWAYS also, not sure if this matters, but I wanted to be able to track the updates.

Let me know if you think it’s worth updating the contact handler, and I think I should update the wiki to note the limitations of the hidden door and wireless open/close sensors. If you agree, I’ll do so.

Regards,

Nick,
Sorry, I’m busy right now, probably until the weekend, but I’ll look at it eventually.
Bernd

Hi @Nicholas_Waterton,

I have run into this exact same problem, hadn’t seen this thread until now, so I started this new topic:

I will take Bernd’s advice, turn on the debug and verify it is the same issue, but I have a strong feeling it is.

Wondering if you have gotten any further on this since your last post in December?

Can you tell me how you enabled the advanced features on your hidden door sensors - like status repeat and heartbeat? I don’t see an option like that from my Insteon app.

@Bernd_Pfrommer

Wondering if the binding mod suggested above made it into the official binding?

Thanks!

Tom,

I couldn’t get the mod to work properly, so I finally gave up on the hidden door sensor, and switched to a zwave sensor instead (also a hidden sensor from Aeon). I use the insteon sensor as a back up sensor (and absolute state indicator, as it updates status every 15 minutes – which is accurate).

If you use Houselinc software, you can program the “advanced states” of the sensor, it’s not in the app.

Nick Waterton P.Eng.
National Support Leader - Nuclear Medicine, PET and RP
GE Healthcare

M+1 416 859 8545
F +1 905 248 3089
E nick.waterton@med.ge.commailto:nick.waterton@med.ge.com

2300 Meadowvale Boulevard
Mississauga, ON L5N 5P9 Canada

GE imagination at work

I don’t think Nick’s mod made it into the repository. I dropped the ball on this one. Got side tracked and completely forgot this was still an open issue. Sorry!

About Nick’s reply: your 2014 Hub does not work with HouseLinc :frowning:

Looks like Nick had some way of getting the sensors to send an update periodically. It may actually solve your problem.
@Nicholas_Waterton, did that affect the battery life noticeably?

Yes, sorry, forgot about the difference in the hubs.

Nick Waterton P.Eng.
National Support Leader - Nuclear Medicine, PET and RP
GE Healthcare

M+1 416 859 8545
F +1 905 248 3089
E nick.waterton@med.ge.commailto:nick.waterton@med.ge.com

2300 Meadowvale Boulevard
Mississauga, ON L5N 5P9 Canada

GE imagination at work

I had a look at Nick’s proposed handler. There are quite a number of changes in it that I wouldn’t want to roll in without further evaluation as to the side effects.

For starters, it publishes always, i.e. StateChangeType.CHANGED is now StateChangeType.ALWAYS. That would defeat the whole duplicate removal, which some users wanted.

Then it actively queries the battery life. This is usually only done for battery-operated devices, and for those we have the “*SleepingContactHandler”. I’m confused now why we are using the handler for the hardwired devices.

Nick, do you still remember what the story was there?

Thanks @Nicholas_Waterton @Bernd_Pfrommer . Do either of you know if there is a way outside of HouseLinc? Is it possible through InsteonTerminal?

Nick,
I’m thinking of moving to those zwave sensors you are referring to for my exterior doors. Are they the same diameter as the Insteon (or larger)? I’d like to plunk them into the same spot and not have an empty hole in my door frame.