Zwave delays

chris · September 22, 2019, 3:27pm

When do you get this error?

rafdalb · September 22, 2019, 3:28pm

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

chris · September 22, 2019, 3:38pm

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 . I will need to try and find the docs on my old computer.

rafdalb · September 22, 2019, 4:53pm

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.

chris · September 22, 2019, 5:36pm

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.

OMR · September 23, 2019, 11:16pm

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.

OMR · September 25, 2019, 5:51pm

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

chris · September 26, 2019, 7:21am

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.

OMR · September 26, 2019, 7:23pm

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.

Thomas_Frank · January 20, 2020, 8:24pm

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

chris · January 20, 2020, 9:25pm

Well, don’t do that

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.

rossko57 · January 20, 2020, 9:28pm

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).

Thomas_Frank · January 20, 2020, 9:47pm

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?

rossko57 · January 20, 2020, 9:51pm

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

5iver · January 20, 2020, 9:51pm

Try healing your network so that the mesh updates.

Thomas_Frank · January 20, 2020, 10:02pm

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

Thomas_Frank · January 20, 2020, 10:10pm

I realised that 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!?

Thomas_Frank · January 21, 2020, 8:49pm

Hmm, today when I came home all radiators are shut
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.

5iver · January 22, 2020, 12:13am

Then disable the daily heal and restart OH.

Thomas_Frank · January 22, 2020, 8:14pm

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?