Z-Wave Lock Quit Working----I Need To Learn More

PeteC · April 2, 2020, 4:43pm

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.

Bruce_Osborne · April 2, 2020, 5:49pm

I have added the z-wave tag here.
In the meantime, the log viewer may help.

https://www.cd-jackson.com/index.php/openhab/zwave-log-viewer

chris · April 2, 2020, 6:27pm

No. The source code is the documentation for a debug log - it’s designed for developers not users…

The log just shows the binding requesting the nonce. No nonce is received so it can’t perform the security handshake and it doesn’t then send the command. The device has ack’d the request, but didn’t (apparently) send the nonce that the binding requested.

Please, when posting logs use code fences so the log is well formatted and readable (thanks).

PeteC · April 2, 2020, 8:17pm

Bruce,
Sorry about the missing tag. I had it set when I started the topic but every time I clicked Create Topic I got some sort of Server error or something.
Then I noticed a Draft button and clicked that. It got my text back and I was able to post it. But the tag must not have survived the draft process.

Also, Chris, I thought the code fence might be the reason for the server error so I deleted it and still got the server errors when I tried to “Create Topic”. When I found the Draft button and saw I could Create from there I edited the topic to paste my log. Sorry for not using the code fence.

I have been using Chris’s Log Viewer but I can’t make sense out of it.
I attached a screen capture of the same section as in the log I posted before. I will reproduce that below also using code fences.

For example, the log view for the look_door seems to end at 11:10:50.660 (or there abouts) but the log I posted goes on until 11:10:55.722.
Maybe I need a “Log View for Dummies” along with an “OpenHAB.log for Dummies”.

Chris, I see your explanation of the problem but there is no way on god’s green earth that I could have made that conclusion myself. Is there no way for a newbie to learn stuff like this except by bugging you guys?

Anyway, do you have any suggestions for what I should do next? Reset the device? Exclude and Include? Something else?

Here is the Log Viewer screen capture and the code fence version of the log.
Thanks.

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.

chris · April 2, 2020, 8:26pm

Well, the ZWave protocol is rather complex - the binding is a good start, and the ZWave protocol documentation is available on the Silabs website. The protocol docs do explain this, but of course, like the binding, they are thousands of pages long, so there’s a lot to learn.

This is what I already looked at, so I can’t really add a lot more than I’ve already said.

You can use my log viewer - this displays things reasonably simply. To understand what the log viewer means, you really need to understand the protocol - that’s not really easy.

I can really only point at the source. The purpose of the documentation is not for users - it is for developers. You can look through the binding source to work out what the debug log entries mean.

You could try resetting the device to see if that helps. You will then need to securely re-install it.

PeteC · April 2, 2020, 9:16pm

I’ll try the reset and if that fails, re-install.

As for docs, I have the 679 page Silicon Labs doc. It doesn’t mention nonce but I found what it stands for (in crypto context).
I also found info that seems to be more readable on the SmartThings site.

I’ll post my results here for others finding this thread.
Thanks

chris · April 2, 2020, 9:17pm

I don’t know what document you have - there are many many documents describing the protocol. IFRC the security is covered in the encapsulation document.

PeteC · April 7, 2020, 12:30am

Well, reset didn’t help so I excluded it and included it. It came back as Node 24 but it was not secure. I must have found a half dozen ways to add secure inclusion going all the way back to 2016. But I have not been able to find the latest way to include securely.

chris · April 7, 2020, 7:15am

Do you have any idea why it’s not working? What do the logs show?

PeteC · April 7, 2020, 5:34pm

Sorry for the delayed response. I have learned that if I am going to do something with OpenHAB I need to set aside at least an hour and most likely will overrun that.
First I used a different procedure to include the lock. This worked for my First Alert CO/Smoke detectors that I gave up on months ago.
Jakdock said to do this:
Include Using Thing Find

That worked and secure=true.
But the lock doesn’t lock. If I click it (in HABPanel) the text changes from “OFF” to “ON” then switches back in a few seconds.
I captured that segment from the Log View:

.
I clicked the “lock” action at 11:59:05.581.
At 11:59:20.243 I see that STATE UPDATE says it is back OFF.
I don’t know enough about it to know why.

Another thing I can’t fathom is the OpenHAB.log in a Putty session stopped at 11:55:05.581 (the first line of the LogView capture).
In Putty I had entered:
tail -f /var/log/openhab2/openhab.log
which normally displays each new line in real time. But for some reason it stopped at 11:55:05.581 otherwise I would have provided that also.

chris · April 7, 2020, 5:38pm

From what I can tell here everything looks fine. Obviously I can’t dig in to this to see more, but I see the secure transactions that appear ok, the lock status updates and responses - all looks fine from what I can see in the image.

PeteC · April 7, 2020, 7:56pm

Great, thank you for your time.
It looks like the ball is in my court now.
BTW, it might be “healing”. It is now reporting “Alarm Types”.
Like “Closed by using the handle”, and "Unsecured by User (User-ID) at Keypad…