Hi,
I own 2 battery-driven Zwave Devices - Sensative Strips door/window sensors. They are reporting the window open/closed changes just fine when opening and closing the window. But once a day, during the daily wakeup, they are switching from closed to open automatically without touching the window, actually without even being at home.
I’m running OpenHab 2.0.0~20161023033000 on Raspberry Pi using the Aeotec AEOEZW090-C Aeon Labs USB Stick. Strips are reported as 11-01-011 Strips-MaZw.
It’s a binary sensor, so OFF means closed and ON means open.
For me it looks like an ON message was queued and got delivered during wakeup. But I’m quite new to ZWave, so I might just as well get the log statements wrong.
Please help me. I don’t get any further on my own. And let me know if you need more data.
Here the debug log of one wakeup. The wrong state was reported for Node 3. You can see the wrong state change at 0:21:01.600.
2016-10-26 20:21:01.407 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 03 02 84 07 71
2016-10-26 20:21:01.416 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-26 20:21:01.420 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 03 02 84 07 71
2016-10-26 20:21:01.423 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 03 02 84 07 71
2016-10-26 20:21:01.426 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 03 02 84 07
2016-10-26 20:21:01.428 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Application Command Request (ALIVE:DONE)
2016-10-26 20:21:01.429 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Starting initialisation from DONE
2016-10-26 20:21:01.431 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@cdb57a already registered
2016-10-26 20:21:01.432 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Incoming command class WAKE_UP
2016-10-26 20:21:01.433 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Received Wake Up Request
2016-10-26 20:21:01.435 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Received WAKE_UP_NOTIFICATION
2016-10-26 20:21:01.436 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Is awake with 3 messages in the wake-up queue.
2016-10-26 20:21:01.437 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
2016-10-26 20:21:01.439 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveWakeUpEvent
2016-10-26 20:21:01.447 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-10-26 20:21:01.447 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-10-26 20:21:01.449 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Transaction not completed: node address inconsistent. lastSent=2, incoming=255
2016-10-26 20:21:01.451 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 02 30 02 25 D2 21
2016-10-26 20:21:01.453 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 30 02 25 D2 21
2016-10-26 20:21:01.467 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2016-10-26 20:21:01.471 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-26 20:21:01.478 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2016-10-26 20:21:01.481 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2016-10-26 20:21:01.487 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2016-10-26 20:21:01.496 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 30 03 FF 3E
2016-10-26 20:21:01.499 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: Sent Data successfully placed on stack.
2016-10-26 20:21:01.505 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-26 20:21:01.508 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 03 03 30 03 FF 3E
2016-10-26 20:21:01.512 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 03 03 30 03 FF 3E
2016-10-26 20:21:01.515 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 03 03 30 03 FF
2016-10-26 20:21:01.517 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Application Command Request (ALIVE:DONE)
2016-10-26 20:21:01.518 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Starting initialisation from DONE
2016-10-26 20:21:01.519 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@cdb57a already registered
2016-10-26 20:21:01.521 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Incoming command class SENSOR_BINARY
2016-10-26 20:21:01.522 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - NODE 3: Received SENSOR_BINARY command V1
2016-10-26 20:21:01.523 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - NODE 3: Sensor Binary report, type=Unknown, value=255
2016-10-26 20:21:01.524 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveBinarySensorValueEvent
2016-10-26 20:21:01.524 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveBinarySensorValueEvent
2016-10-26 20:21:01.525 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_BINARY, value = 255
2016-10-26 20:21:01.526 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:controller:node3:sensor_binary to ON [OnOffType]
2016-10-26 20:21:01.530 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=3, callback=210, payload=03 02 30 02
2016-10-26 20:21:01.539 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 03 03 30 03 FF
2016-10-26 20:21:01.543 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=210, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2016-10-26 20:21:01.544 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 D2 00 00 08 31
2016-10-26 20:21:01.544 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-26 20:21:01.545 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-10-26 20:21:01.545 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-10-26 20:21:01.547 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-26 20:21:01.547 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Response processed after 91ms/336ms.
2016-10-26 20:21:01.548 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 D2 00 00 08 00 00 3F
2016-10-26 20:21:01.553 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 D2 00 00 08 00 00 3F
2016-10-26 20:21:01.554 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=D2 00 00 08
2016-10-26 20:21:01.555 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 210, Status = Transmission complete and ACK received(0)
2016-10-26 20:21:01.557 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Starting initialisation from DONE
2016-10-26 20:21:01.558 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@cdb57a already registered
2016-10-26 20:21:01.560 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=3, callback=210, payload=03 02 30 02
2016-10-26 20:21:01.564 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=D2 00 00 08
2016-10-26 20:21:01.565 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=210, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2016-10-26 20:21:01.566 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-10-26 20:21:01.568 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 13 03 05 71 04 00 07 01 25 D3 63
2016-10-26 20:21:01.569 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 0C 00 13 03 05 71 04 00 07 01 25 D3 63
2016-10-26 20:21:01.579 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 30 03 FF 3E
2016-10-26 20:21:01.583 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-26 20:21:01.584 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (CAN), resending
2016-10-26 20:21:01.590 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 03 03 30 03 FF 3E
2016-10-26 20:21:01.591 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 03 03 30 03 FF 3E
2016-10-26 20:21:01.593 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 03 03 30 03 FF
2016-10-26 20:21:01.594 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Application Command Request (ALIVE:DONE)
2016-10-26 20:21:01.594 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Starting initialisation from DONE
2016-10-26 20:21:01.595 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@cdb57a already registered
2016-10-26 20:21:01.596 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Incoming command class SENSOR_BINARY
2016-10-26 20:21:01.596 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - NODE 3: Received SENSOR_BINARY command V1
2016-10-26 20:21:01.597 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - NODE 3: Sensor Binary report, type=Unknown, value=255
2016-10-26 20:21:01.598 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveBinarySensorValueEvent
2016-10-26 20:21:01.598 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveBinarySensorValueEvent
2016-10-26 20:21:01.599 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_BINARY, value = 255
2016-10-26 20:21:01.600 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:controller:node3:sensor_binary to ON [OnOffType]
2016-10-26 20:21:01.602 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=3, callback=211, payload=03 05 71 04 00 07 01
2016-10-26 20:21:06.571 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2016-10-26 20:21:06.576 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Sending ABORT Message = 01 03 00 16 EA
2016-10-26 20:21:06.577 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2016-10-26 20:21:06.578 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA
2016-10-26 20:21:06.579 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!
2016-10-26 20:21:06.579 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Is sleeping
2016-10-26 20:21:06.580 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Putting message SendData in wakeup queue.
Thank you very much!