I have a 914TRL lock that has been working fine for many months. Recently it quit responding to Lock/Unlock commands.
I have been puzzling over the openhab.log for days and concluded I need to know more about what the log entries mean. I often see Chris and others helping with a problem by viewing the log and picking out the problem. I feel that is an unfair burden placed on a few experts. But I have not been able to find a Doc that explains what the log entries mean. Can someone point me to such a Doc?
I have searched the openHAB community and can’t find a solution to my problem. The paperUI Properties report “zwave_secure true”.
The lock keeps reporting tons of entries. Probably 10 or 100 times as many entries then my thermostat and CO detectors.
Below are the log entries that appear when I initiate a “Lock”.
2020-04-02 11:10:50.588 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:fe40ab17:node7:lock_door --> ON [OnOffType]
2020-04-02 11:10:50.592 [DEBUG] [mmandclass.ZWaveDoorLockCommandClass] - NODE 7: Creating new message for application command DOORLOCK_SET, value 255
2020-04-02 11:10:50.598 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: SECURITY required on COMMAND_CLASS_DOOR_LOCK
2020-04-02 11:10:50.601 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: Command Class COMMAND_CLASS_DOOR_LOCK is required to be secured
2020-04-02 11:10:50.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Bump transaction 261 priority from Get to Immediate
2020-04-02 11:10:50.608 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Adding to device queue
2020-04-02 11:10:50.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Added 261 to queue - size 8
2020-04-02 11:10:50.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-04-02 11:10:50.618 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 7: isNonceAvailable = null
2020-04-02 11:10:50.620 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_GET version 1
2020-04-02 11:10:50.625 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 07 02 98 40 25 A4 B9
2020-04-02 11:10:50.629 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 7: Sending REQUEST Message = 01 09 00 13 07 02 98 40 25 A4 B9
2020-04-02 11:10:50.633 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-04-02 11:10:50.635 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-04-02 11:10:50.638 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-04-02 11:10:50.638 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 262: [WAIT_RESPONSE] priority=High, requiresResponse=true, callback: 164
2020-04-02 11:10:50.643 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2020-04-02 11:10:50.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-04-02 11:10:50.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 262: [WAIT_RESPONSE] priority=High, requiresResponse=true, callback: 164
2020-04-02 11:10:50.647 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling initialised at 86400 seconds - start in 1500 milliseconds.
2020-04-02 11:10:50.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-04-02 11:10:50.650 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-02 11:10:50.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2020-04-02 11:10:50.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-02 11:10:50.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2020-04-02 11:10:50.660 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 A4 00 00 02 4D
2020-04-02 11:10:50.660 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 262: [WAIT_RESPONSE] priority=High, requiresResponse=true, callback: 164
2020-04-02 11:10:50.663 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-04-02 11:10:50.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 262: [WAIT_RESPONSE] priority=High, requiresResponse=true, callback: 164
2020-04-02 11:10:50.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=164, payload=A4 00 00 02
2020-04-02 11:10:50.669 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2020-04-02 11:10:50.671 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: sentData successfully placed on stack.
2020-04-02 11:10:50.672 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 262: Advanced to WAIT_REQUEST
2020-04-02 11:10:50.675 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: TID 262: Transaction not completed
2020-04-02 11:10:50.677 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=164, payload=A4 00 00 02
2020-04-02 11:10:50.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 262: [WAIT_REQUEST] priority=High, requiresResponse=true, callback: 164
2020-04-02 11:10:50.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-04-02 11:10:50.682 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 262: [WAIT_REQUEST] priority=High, requiresResponse=true, callback: 164
2020-04-02 11:10:50.683 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 262: (Callback 164)
2020-04-02 11:10:50.685 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-04-02 11:10:50.687 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 262: callback 164
2020-04-02 11:10:50.689 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=164, payload=A4 00 00 02
2020-04-02 11:10:50.691 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: SendData Request. CallBack ID = 164, Status = Transmission complete and ACK received(0)
2020-04-02 11:10:50.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 262: Advanced to WAIT_DATA
2020-04-02 11:10:50.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: TID 262: Transaction not completed
2020-04-02 11:10:50.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-02 11:10:50.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-02 11:10:52.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling...
2020-04-02 11:10:52.148 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling deferred until initialisation complete
2020-04-02 11:10:55.695 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 7: TID 262: Timeout at state WAIT_DATA. 3 retries remaining.
2020-04-02 11:10:55.697 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 262: Transaction CANCELLED
2020-04-02 11:10:55.708 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-04-02 11:10:55.711 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: notifyTransactionResponse TID:262 CANCELLED
2020-04-02 11:10:55.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: processing secure transaction -- TID:261
2020-04-02 11:10:55.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.