I’m can’t get my Insteon Motion Sensor 2420M to trigger any events in OpenHAB 1.8.3 - but I can get it to directly turn on an Insteon light itself and see messages from it in Insteon Terminal.
OpenHAB finds the device (14.2E.40) in the modem database:
2016-10-05 21:10:49.540 [INFO ] [.o.b.i.InsteonPLMActiveBinding] - device 14.2E.40 found in the modem database and the modem controls groups [0x01] and responds to groups [0x01].
However it never seems to process messages from the motion sensor - with Insteon binding TRACE logging level I never see any messages from the motion sensor.
Insteon Terminal sees messages from the motion sensor:
This is most mysterious. If you switch on debug logging in the insteonplm binding, it should log every incoming message. The bottom layer of the insteon terminal is very similar to the insteonplm binding, and neither of them should drop any messages.
I think the 3:2 at the end means: 3 hops retransmissions maximum allowed, it took 2 hops to reach you.
questions:
Is the insteon terminal using the same PLM modem as the insteon binding?
are you using an insteon hub?
Your motion sensor is not too old. As long as it produces any messages we should be able to get it to work.
Yes, Insteon Terminal and OpenHAB are using the same PLM modem
No, I am not using an Insteon HUB
I enabled trace level logging for the insteonplm binding (before I only had it on the insteon binding), here is the output when the motion sensor detected movement:
2016-10-08 00:07:44 DEBUG o.o.b.i.InsteonPLMActiveBinding[:581]- got msg: IN:Cmd:0x50|fromAddress:14.2E.40|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2016-10-08 00:07:44 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:14.2E.40|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2016-10-08 00:07:44 DEBUG o.o.b.i.i.d.MessageDispatcher[:70]- all link message is no duplicate: true/true
2016-10-08 00:07:44 DEBUG o.o.b.i.i.d.MessageDispatcher[:72]- 14.2E.40:MotionSensorData->NoOpMsgHandler cmd1:0x11 group 1/1:IN:Cmd:0x50|fromAddress:14.2E.40|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2016-10-08 00:07:44 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:14.2E.40|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2016-10-08 00:07:44 DEBUG o.o.b.i.i.d.MessageDispatcher[:70]- all link message is no duplicate: true/true
2016-10-08 00:07:44 DEBUG o.o.b.i.i.d.MessageDispatcher[:72]- 14.2E.40:WirelessMotionSensorContact->OpenedSleepingContactHandler cmd1:0x11 group 1/1:IN:Cmd:0x50|fromAddress:14.2E.40|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x11|command2:0x01|
2016-10-08 00:07:44 DEBUG o.o.b.i.i.device.DeviceFeature[:264]- 14.2E.40:WirelessMotionSensorContact publishing: OPEN
2016-10-08 00:07:44 DEBUG o.o.b.i.i.device.InsteonDevice[:379]- qe taken off direct: WirelessMotionSensorContact(1:1:5) OUT:Cmd:0x62|toAddress:14.2E.40|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|
2016-10-08 00:07:44 DEBUG o.o.b.i.i.device.InsteonDevice[:399]- next request queue processed in 2000 msec, quiettime = 2000
2016-10-08 00:07:44 DEBUG o.o.b.i.internal.driver.Port[:382]- writing (500): OUT:Cmd:0x62|toAddress:14.2E.40|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|
2016-10-08 00:07:44 DEBUG o.o.b.i.i.device.DeviceFeature[:264]- 14.2E.40:GenericLastTime publishing: 2016-10-08T00:07:44
2016-10-08 00:07:45 DEBUG o.o.b.i.InsteonPLMActiveBinding[:581]- got msg: IN:Cmd:0x50|fromAddress:14.2E.40|toAddress:23.9B.8A|messageFlags:0x2B=ACK_OF_DIRECT:3:2|command1:0x2E|command2:0x00|
2016-10-08 00:07:45 DEBUG o.o.b.i.i.d.MessageDispatcher[:134]- 14.2E.40:WirelessMotionSensorContact DIRECT_ACK: q:QUERY_PENDING cmd: 80
2016-10-08 00:07:45 DEBUG o.o.b.i.i.d.MessageDispatcher[:139]- changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:14.2E.40|toAddress:23.9B.8A|messageFlags:0x2B=ACK_OF_DIRECT:3:2|command1:0x2E|command2:0x00|
2016-10-08 00:07:45 DEBUG o.o.b.i.i.d.MessageDispatcher[:159]- defdisp: 14.2E.40:WirelessMotionSensorContact set status to: QUERY_ANSWERED
2016-10-08 00:07:45 DEBUG o.o.b.i.i.device.DeviceFeature[:264]- 14.2E.40:GenericLastTime publishing: 2016-10-08T00:07:45
2016-10-08 00:07:45 DEBUG o.o.b.i.InsteonPLMActiveBinding[:581]- got msg: IN:Cmd:0x51|fromAddress:14.2E.40|toAddress:23.9B.8A|messageFlags:0x1B=DIRECT:3:2|command1:0x2E|command2:0x00|userData1:0x00|userData2:0x01|userData3:0x64|userData4:0x01|userData5:0x80|userData6:0x0E|userData7:0x7F|userData8:0x7B|userData9:0x0A|userData10:0x02|userData11:0x00|userData12:0x71|userData13:0x00|userData14:0xD2|
2016-10-08 00:07:45 DEBUG o.o.b.i.i.d.MessageHandler[:641]- MotionSensorDataReplyHandler: 14.2E.40 got light level: 0, battery level: 113
2016-10-08 00:07:45 DEBUG o.o.b.i.i.device.DeviceFeature[:250]- 14.2E.40:MotionSensorData publishing: 0
2016-10-08 00:07:45 DEBUG o.o.b.i.i.device.DeviceFeature[:250]- 14.2E.40:MotionSensorData publishing: 113
2016-10-08 00:07:45 DEBUG o.o.b.i.i.d.MessageDispatcher[:151]- 14.2E.40:WirelessMotionSensorContact->NoOpMsgHandler DIRECT
2016-10-08 00:07:45 DEBUG o.o.b.i.i.device.DeviceFeature[:264]- 14.2E.40:GenericLastTime publishing: 2016-10-08T00:07:45
2016-10-08 00:07:46 DEBUG o.o.b.i.i.d.RequestQueueManager[:132]- device queue for 14.2E.40 is empty!
A little nitpick: looks like you have DEBUG, not TRACE enabled. Good, because the TRACE log is hard to read, and you can get from DEBUG all you need.
Look at this line:
The binding is publishing the Open/Close event to the openhab bus! Check the openhab “events” log. Do you see the events there? You should.
I also see the binding publishing battery and light level. Do you have an item for that as well? Not that it would matter as far as the open/close functionality is concerned.
2016-10-08 00:07:45 - StairDownstairsSensorBatteryLevel state updated to 113
2016-10-08 12:53:47 - StairDownstairsSensor state updated to OPEN
2016-10-08 12:53:48 - StairDownstairsSensorLightLevel state updated to 76
2016-10-08 12:55:38 - StairDownstairsSensor state updated to CLOSED
2016-10-08 13:11:05 - StairDownstairsSensor state updated to OPEN
2016-10-08 13:11:06 - StairDownstairsSensorLightLevel state updated to 112
Yes, I have StairDownstairsSensorBatteryLevel and StairDownstairsSensorLightLevel items (see log entries above).
I also needed to change my rule from using “received command” to “received update”.
Now I just need to watch it to see if the motion sensor updates are reliable.
Now this is odd. I see the Insteon messages in the insteonplm log each time the motion sensor is triggered, but the item state is only changing (and in the event log) every other time - every other OPEN-CLOSE is being ignored.
Looks like a whole bunch of messages do not make it through on the first go. You are supposed to get:
BCAST
CLEAN
SUCCESS
I only see BCAST (first event)
and BCAST+CLEAN (second event)
Since in the first case it did no get CLEAN and SUCCESS, it treated the subsequent BCAST from the second event as duplicate of the first event, and discarded it.
It is 100% consistent that it happens every other OPEN/CLOSE cycle - I wonder if it is a flaw with the 2420M rather than a problem with my Insteon network. I’ll let you know if I’m able to figure anything else out.
I unlinked the PLM and the 2420M (using Insteon Terminal to verify), did a factory reset of the 2420M, and relinked the PLM and 2420M (both directions) - but same results: OpenHAB 1.8.3 ignores every other OPEN/CLOSE pair.
