Zwave delays

When I try to mark the device as failed on HABmin…

And this is the log I see when I try to run the command:

2019-09-22 17:29:31.384 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Configuration update received
2019-09-22 17:29:31.392 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Configuration update set action_failed to true (Boolean)
2019-09-22 17:29:31.396 [DEBUG] [message.RemoveFailedNodeMessageClass] - NODE 13: Marking node as having failed.
2019-09-22 17:29:31.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 818 to queue - size 1
2019-09-22 17:29:31.404 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-22 17:29:31.408 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 61 0D 01 7C E8 
2019-09-22 17:29:31.412 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 61 0D 01 7C E8 
2019-09-22 17:29:31.417 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-22 17:29:31.419 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-22 17:29:31.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 818: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 124
2019-09-22 17:29:31.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 17:29:31.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 17:29:31.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 818: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 124
2019-09-22 17:29:31.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-22 17:29:31.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 17:29:31.441 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 61 08 93 
2019-09-22 17:29:31.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 17:29:31.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2019-09-22 17:29:31.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2019-09-22 17:29:31.461 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 818: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 124
2019-09-22 17:29:31.464 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-22 17:29:31.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 818: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 124
==> /var/log/openhab2/events.log <==
2019-09-22 17:29:31.471 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:aeotec:node13' has been updated.
==> /var/log/openhab2/openhab.log <==
2019-09-22 17:29:31.471 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
==> /var/log/openhab2/events.log <==
2019-09-22 17:29:31.474 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
==> /var/log/openhab2/openhab.log <==
2019-09-22 17:29:31.484 [DEBUG] [message.RemoveFailedNodeMessageClass] - Got RemoveFailedNode response.
2019-09-22 17:29:31.486 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 13: Remove failed node failed as node not found
2019-09-22 17:29:31.489 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 818: Transaction COMPLETED
==> /var/log/openhab2/events.log <==
2019-09-22 17:29:31.494 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@55d0ca
==> /var/log/openhab2/openhab.log <==
2019-09-22 17:29:31.497 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveNetworkEvent
2019-09-22 17:29:31.500 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 80ms
2019-09-22 17:29:31.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 818: Transaction completed
2019-09-22 17:29:31.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:818 DONE
2019-09-22 17:29:31.508 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 17:29:31.510 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-22 17:29:40.810 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 10 02 84 07 62 
2019-09-22 17:29:40.814 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=16, callback=0, payload=00 10 02 84 07 
2019-09-22 17:29:40.817 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=16, callback=0, payload=00 10 02 84 07 
2019-09-22 17:29:40.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-22 17:29:40.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Application Command Request (ALIVE:DONE)
2019-09-22 17:29:40.822 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: resetResendCount initComplete=true isDead=false
2019-09-22 17:29:40.823 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Is awake with 0 messages in the queue
2019-09-22 17:29:40.825 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Start sleep timer at 1000ms
2019-09-22 17:29:40.827 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2019-09-22 17:29:40.848 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 16: Node Status event - Node is AWAKE
2019-09-22 17:29:40.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Commands processed 1.
2019-09-22 17:29:40.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1ea09de.
2019-09-22 17:29:40.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
==> /var/log/openhab2/events.log <==
2019-09-22 17:29:40.853 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:aeotec:node16' has been updated.
==> /var/log/openhab2/openhab.log <==
2019-09-22 17:29:40.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-22 17:29:40.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 17:29:40.859 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-22 17:29:41.327 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: WakeupTimerTask 0 Messages waiting, state DONE
2019-09-22 17:29:41.827 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: WakeupTimerTask 0 Messages waiting, state DONE
2019-09-22 17:29:41.828 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: No more messages, go back to sleep
2019-09-22 17:29:41.830 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 16: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
2019-09-22 17:29:41.831 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY not supported
2019-09-22 17:29:41.833 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
2019-09-22 17:29:41.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@11fdc7
2019-09-22 17:29:41.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Bump transaction 819 priority from Immediate to Immediate
2019-09-22 17:29:41.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue
2019-09-22 17:29:41.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Added 819 to queue - size 5
2019-09-22 17:29:41.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-22 17:29:41.843 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 10 02 84 08 25 7D 23 
2019-09-22 17:29:41.845 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 09 00 13 10 02 84 08 25 7D 23 
2019-09-22 17:29:41.847 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-22 17:29:41.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 819: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 125
2019-09-22 17:29:41.850 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-22 17:29:41.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 17:29:41.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 17:29:41.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 819: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 125
2019-09-22 17:29:41.856 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-09-22 17:29:41.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-22 17:29:41.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 17:29:41.860 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 17:29:41.860 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 17:29:41.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 17:29:41.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 819: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 125
2019-09-22 17:29:41.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-22 17:29:41.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 819: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 125
2019-09-22 17:29:41.874 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 17:29:41.876 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 16: sentData successfully placed on stack.
2019-09-22 17:29:41.877 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 819: Advanced to WAIT_REQUEST
2019-09-22 17:29:41.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 819: Transaction not completed
2019-09-22 17:29:41.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 17:29:41.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 17:29:46.185 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 7D 01 01 B1 27 
2019-09-22 17:29:46.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=125, payload=7D 01 01 B1 
2019-09-22 17:29:46.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=125, payload=7D 01 01 B1 
2019-09-22 17:29:46.196 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 819: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 125
2019-09-22 17:29:46.198 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-22 17:29:46.200 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 819: [WA

I believe that this means that the device is not considered failed by the controller, but Silabs have removed the documentation from their website now as the close down access to the new API :weary:. I will need to try and find the docs on my old computer.

1 Like

That means Zensys tools would not be able to remove the device anyway. I assume, I’m wondering how to fix the issue then;

should I reset everything (although I would like to avoid it, just to understand what’s the alternative)?

Thanks,
Raf.

Some people have been able to use the Zensys tool to remove devices, and some can’t. We spent some time a year or so back confirming that the binding is sending exactly the same commands as the Zensys tool, so I think it’s likely that you will have he same result.

1 Like

It’s been a while, but I remember I sometimes had to try several times in order to successfully remove nodes in Zensys. It always worked in the end though.

1 Like

My Z-Wave network acted up again today.
Was able to ‘sneak’ past a sensor without any lights turning on. Hitting a Z-Wave wall switch. Took 10s for the Zigbee lights to go off, Z-Wave lights in group stayed on.

Using my z-wave sniffer I immediately noticed 2 nodes spewing out messages completely swamping the network. Power-cycled them; sniffer logs calmed down and wall switch worked fine again.

Nodes that acted up this time was (differs) : ZW096 Smart Switch 6 & HEATIT Z-RELAY Multipurpose relay

Was this also visible in the openhab log? This is not as uncommon an event as you’d hope and I’m wondering if it’s something I could add some sort of indicator for in the binding. If you have the log showing this, please can you provide it.

Sorry no. Debug logging was off and I was a bit in a hurry to rectify.
Will try enabling debug logs when it happens again.
This time all messages was addressed correctly to the controller.
Last time they were addressed to a non excisting node.

Hi everybody,
now i have encountered a similar problem.
After I upgraded my system to an RPI4 and the actual snapshot releas2 my zwave is buggy.
Often I have a delay of several minutes(?) on an random zwave devices.

I can force this behavior by cutting the power off a fibaro switch. After doing that another switch isn’t responding for several seconds/minutes.

My question, before digging deeper into the system and logs: was there a change in the zwave binding, that could explain this behavior?
Before christmas, with my old configuration (2.4 I think) there was no problem and now with openHAB 2.5.1-2 (Release Build) , my home automation is not as reliable as before :frowning:

Well, don’t do that :wink:

The problem is that if there are retries in the network, then these will take some time. The retry period is 5s, and the binding will perform 3 retries. This is the same as it has always been - there’s no change in this for a long time.

Does this offer clues? Is there something in the net trying to actively poll that device (and so clagging the network with retries upon its removal).

No, this device is normaly offline and I don’t use it in my rules. Only befor I switch of its ‘master’. Before that I send a off command to this switch and wait a little moment…
And the last year I didn’t have any problem with it.
Nowerdsays randomly some rollershutter doesn’t open or light don’t turn on or off or atleast delayed.
But yes, I thing the retries from the controller will slower the network.
But why have I the same problem over the day, when this device is offline for several hours?

@Thomas_Frank if you think your network is retrying and you don’t know why …

Try healing your network so that the mesh updates.

Next point on my list. But I don’t know if I can understand the output :frowning:

I realised that :sweat_smile: but no problem with this config in the last year.
But now after I had to use a new controller I first realised some cancle messages in the log. I managed to restore the old uzb1, but the random messages don’ t disappear. But I thnik they are to seldom to force this behavior!?

Hmm, today when I came home all radiators are shut :frowning:
Four of five window contacts couldn’t send the close command or wasn’t received.
I had to open and close one window several times before the radiator got the heating command.
The other windows / radiators acted then immediately.
Later I tryed a light switch. It took 2 minutes until the light goes on. The next commands were processed with no delay. Even after poweroff this special actor, no delay today…

I searched the net for a sniffer SW but couldn’t find one. And I don’t know if I could use my spare ZME UZB1 for this job.

Then disable the daily heal and restart OH.

Tryed this in the afternoon. The map didn’t change…
But at the moment, since this morning all funktions worked as expected.

I will leave the daily heal disabled, because my sensors didn’t move. Right?

Yes.