ZWave frozen

Setup, Configuration and Use Runtime
, ,
1

I’m scratching my head over why my ZWave has all frozen today. Was all working smoothly last night and has been fine for months… but today it’s all weird… Can’t turn anything on or off.

If I turn devices on/off from the app or switches the logs quickly reflect the change correctly but the devices/lights do nothing.

The Zstick LED starts cycling when I plug it in but after about 10-20 secs it stops and shows a solid light. That colour does seem to change occasionally, so it’s doing something.

Got debug turned on and see various things in the logs (small extract below)…

Any pointers/suggestions/reminders for things to try/test/look out for?

I’m running the latest stable Openhabian on a Pi 4 Model B with an Aeotec Zstick. As part of investigating the issue I have made sure the OS and OH versions are all updated to the latest stable.

2020-10-11 14:25:55.484 [vent.ItemStateChangedEvent] - CurrentTime changed from 2020-10-11T14:24:55.449+0100 to 2020-10-11T14:25:55.452+0100

==> /var/log/openhab2/openhab.log <==
2020-10-11 14:19:56.596 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 408: Transaction CANCELLED
2020-10-11 14:19:56.598 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 46: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-10-11 14:19:56.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 46: notifyTransactionResponse TID:408 CANCELLED
2020-10-11 14:19:56.603 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-10-11 14:19:56.606 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 33 03 32 01 30 25 A0 50
2020-10-11 14:19:56.609 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 51: Sending REQUEST Message = 01 0A 00 13 33 03 32 01 30 25 A0 50
2020-10-11 14:21:11.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 62: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1e2aa28
2020-10-11 14:24:58.767 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 75: Polling…
2020-10-11 14:25:44.223 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling…
2020-10-11 14:25:44.225 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling deferred until initialisation complete

==> /var/log/openhab2/events.log <==
2020-10-11 14:26:55.490 [vent.ItemStateChangedEvent] - CurrentTime changed from 2020-10-11T14:25:55.452+0100 to 2020-10-11T14:26:55.455+0100

==> /var/log/openhab2/openhab.log <==
2020-10-11 14:27:45.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@27f8cc

==> /var/log/openhab2/events.log <==
2020-10-11 14:27:55.493 [vent.ItemStateChangedEvent] - CurrentTime changed from 2020-10-11T14:26:55.455+0100 to 2020-10-11T14:27:55.458+0100

==> /var/log/openhab2/openhab.log <==
2020-10-11 14:27:58.495 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-10-11 14:27:58.498 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-10-11 14:27:58.498 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-10-11 14:27:58.501 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 409: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 160
2020-10-11 14:27:58.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-10-11 14:27:58.504 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Adding to device queue
2020-10-11 14:27:58.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Added 413 to queue - size 43
2020-10-11 14:27:58.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 409: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 160
2020-10-11 14:27:58.510 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-10-11 14:27:58.503 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-10-11 14:27:58.514 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 62: Adding to device queue
2020-10-11 14:27:58.517 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 62: Added 412 to queue - size 44
2020-10-11 14:27:58.514 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-10-11 14:27:58.518 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-10-11 14:27:58.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-10-11 14:27:58.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-10-11 14:27:58.525 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-10-11 14:27:58.526 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-10-11 14:27:58.529 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 409: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 160
2020-10-11 14:27:58.530 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-10-11 14:27:58.532 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-10-11 14:27:58.534 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-10-11 14:28:00.505 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 51: TID 409: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2020-10-11 14:28:00.507 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2020-10-11 14:28:00.510 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 409: Transaction ABORTED
2020-10-11 14:28:00.513 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2020-10-11 14:28:00.516 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA
2020-10-11 14:28:00.518 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-10-11 14:28:00.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-10-11 14:28:12.512 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 51: TID 409: Timeout at state ABORTED. 3 retries remaining.
2020-10-11 14:28:12.514 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 409: Transaction is current transaction, so clearing!!!
2020-10-11 14:28:12.517 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 409: Transaction CANCELLED
2020-10-11 14:28:12.518 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-10-11 14:28:12.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: notifyTransactionResponse TID:409 CANCELLED
2020-10-11 14:28:12.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-10-11 14:28:12.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 409: Transaction event listener: DONE: CANCELLED →
2020-10-11 14:28:12.527 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 51: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@dfed64
2020-10-11 14:28:12.528 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 3E A5
2020-10-11 14:28:12.529 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 51: Node Init transaction completed with response COMPLETE
2020-10-11 14:28:12.531 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 3E A5
2020-10-11 14:28:12.531 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: SECURITY not supported
2020-10-11 14:28:12.533 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: Command Class COMMAND_CLASS_METER is NOT required to be secured
2020-10-11 14:28:12.535 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 51: ZWaveCommandClassTransactionPayload - send to node
2020-10-11 14:28:12.537 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: SECURITY not supported
2020-10-11 14:28:12.538 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: Command Class COMMAND_CLASS_METER is NOT required to be secured
2020-10-11 14:28:12.540 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@2bdd16

==> /var/log/openhab2/events.log <==
2020-10-11 14:28:55.496 [vent.ItemStateChangedEvent] - CurrentTime changed from 2020-10-11T14:27:55.458+0100 to 2020-10-11T14:28:55.461+0100

Thanks

2

Z-Wave log viewer.

Is that a zstick plugged into a USB3 port on the Pi 4? That is a known issue with the stick. You need to plug the stick into a USB2 hub and then connect that to the Pi. The Pi thinks the stick supports USB3 when it does not.

3

Thanks Bruce. Found the USB3 issue early on, so the stick is plugged into a hub :-).

All been working great for months since I moved it all across to Openhabian. Woke up this morning to find nothing worked… Not touched the thing or made any changes to the config in months. Last actual login to the Pi was a minor OS/OH update a month or so ago and it’s been working fine since (until today)…

4

Seeing a few “Polling deferred until initialisation complete” - wondering what’s still initialising?

5

A battery operated device?

6

Hi, I just encountered this very same issue. However, it was not so out of nowhere from my side. I bought some new Honeywell switches for a remodeling on one of my rooms, and had to update the Z-Wave binding in order to include the new updates to the database.

While running Openhab2, I have a Gen5 Aeotec SW090-A stick managed on an ubuntu environment, not the openHabian build.

As I was saying, I successfully included the new devices, but old devices managed to prompt up the “device unknown” issue. The first problem on my side was the missing wakeup/inclusion of the devices. I was sure this was the issue and not DB related as at least another device of the same make-model was working fine and had the manufacturer/deviceID/etc all loading properly.

After failing to heal the devices naturally through the night, I was forced to exclude the 3 affected nodes. HOWEVER, here is were my fuckup starts (i believe). I flagged all three nodes as FAILed, placed the stick on exclusion mode, and then exluded all the nodes. Everything was done through the Paper UI in OpenHab2. I did a factory reset on all three devices, and then paired them with natural pairing mode of the stick. I rebooted the computer, launched Openhab and all its dependencies manually. Finally, got the same behavior as you describe. Aside from that, the controller now initializes all the devices properly; but the three nodes that I excluded are still there as unknown devices!

The Aeotec stick works properly when outside of the OpenHab2 environment. I tested it with a previous deployment build (where I used a Z-Wave app). However, as soon as OpenHab2 loads the stick starts to freeze. My beast guess is that it’s being tormented by the ghost initialization of these phantom nodes. Or OpenHab is actually sending a persistent command that will not let the controller behave as the master of the network.

Hope we will find a solution soon.

7

You likely have similar symptoms but a different issue. Trying to resolve multiple issues in one thread gets confusing.

OpenHAB has never had a separate Z-Wave app.

8

Quick update… so after talking to the Aeotec folks (very good BTW) it looks like my intermittent freezing issue is due to their buffer filling up… so next time it happens I need to check the logs to see what all the z-wave activity is… wish me luck… Not happened again for the last few weeks…

1 Like