Z-Wave commands not being processed

Hello everybody,

I am running openHAB 3.0.2 on a raspi with the Aeotec z-wave stick.
Since yesterday my Z-Wave commands (e.g. switch lights on/off on a FibaroDimmer) do not get processed or take longer that it used to be. NODE 19 is the light dimmer.

Output for Node 19

tail -f -n 1550 /var/log/openhab/openhab.log |grep "NODE 19"
2021-06-01 10:20:08.085 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Commands processed 1.
2021-06-01 10:20:08.086 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1f6651.
2021-06-01 10:20:11.225 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Command received zwave:device:099d457d:node19:switch_dimmer1 --> OFF [OnOffType]
2021-06-01 10:20:11.226 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 19: Creating new message for command SWITCH_MULTILEVEL_SET
2021-06-01 10:20:11.227 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: Encapsulating message, instance / endpoint 1
2021-06-01 10:20:11.228 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 19: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2021-06-01 10:20:11.228 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2021-06-01 10:20:11.229 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2021-06-01 10:20:11.230 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2021-06-01 10:20:11.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Added 137 to queue - size 11
2021-06-01 10:20:11.233 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Polling initialised at 86400 seconds - start in 1500 milliseconds.
2021-06-01 10:20:12.733 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Polling...
2021-06-01 10:20:14.652 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 19: Sending REQUEST Message = 01 0E 00 13 13 07 60 0D 01 01 26 01 00 25 75 EC
2021-06-01 10:20:14.665 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 19: sentData successfully placed on stack.
2021-06-01 10:20:14.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: TID 137: Transaction not completed
2021-06-01 10:20:14.684 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 19: SendData Request. CallBack ID = 117, Status = Transmission complete and ACK received(0)
2021-06-01 10:20:14.685 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: resetResendCount initComplete=true isDead=false
2021-06-01 10:20:14.687 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Response processed after 33ms
2021-06-01 10:20:14.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: TID 137: Transaction completed
2021-06-01 10:20:14.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: notifyTransactionResponse TID:137 DONE
2021-06-01 10:20:14.690 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2021-06-01 10:20:14.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Application Command Request (ALIVE:DONE)
2021-06-01 10:20:14.994 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: resetResendCount initComplete=true isDead=false
2021-06-01 10:20:14.996 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2021-06-01 10:20:14.997 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1
2021-06-01 10:20:14.998 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2021-06-01 10:20:14.998 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 19: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2021-06-01 10:20:14.999 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 19: Switch Multi Level report, value = 0
2021-06-01 10:20:15.000 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2021-06-01 10:20:15.001 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=0
2021-06-01 10:20:15.002 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Updating channel state zwave:device:099d457d:node19:switch_dimmer1 to 0 [PercentType]
2021-06-01 10:20:15.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Commands processed 1.
2021-06-01 10:20:15.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@68cece.
2021-06-01 10:20:18.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Application Command Request (ALIVE:DONE)
2021-06-01 10:20:18.047 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: resetResendCount initComplete=true isDead=false
2021-06-01 10:20:18.048 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2021-06-01 10:20:18.049 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 1
2021-06-01 10:20:18.050 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: SECURITY NOT required on COMMAND_CLASS_SENSOR_MULTILEVEL
2021-06-01 10:20:18.051 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 19: Received COMMAND_CLASS_SENSOR_MULTILEVEL V4 SENSOR_MULTILEVEL_REPORT
2021-06-01 10:20:18.052 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 19: Sensor Type = Power(4), Scale = 0
2021-06-01 10:20:18.053 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 19: Sensor Value = 0E+1
2021-06-01 10:20:18.054 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2021-06-01 10:20:18.055 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=0E+1
2021-06-01 10:20:18.056 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 19: Sensor conversion not performed for POWER.
2021-06-01 10:20:18.057 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Updating channel state zwave:device:099d457d:node19:sensor_power1 to 0 [DecimalType]
2021-06-01 10:20:18.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Commands processed 1.
2021-06-01 10:20:18.059 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@761012.

For some reason the zwave controller lost also randomly the serial port

/dev/ttyACM1

Any help would be appreciated.
regards,
philip

After several reboots, and triggering “network heal” it looks like the net is getting back to normal and the commands get processed right away.

Since I updated my RPI3+ yesterday or so, I’ve been having the same problem. I thought it might have been the device I replaced yesterday but I just turned it off with no change. I thought maybe letting it heal would help, but I let it sit overnight and nothing changed. I have a Z-wave analyzer and I can see lots and lots of routing errors and retries. I tried finding where to change the heal time, but failed so I’ve no idea if the heal actually ran.

Ira

I placed an USB powered hub between the Zwave stick and the pi. That worked for me, but it is not the nicest solution to solve a software problem with hardware. But if it works, it works.

It is actually a problem, likely a hardware one, in the USB stick not responding correctly. The Pi thinks it supports USB 3.

The manufacturer released a new model that corrects the problem. They would not have done that for a firmware issue.

Nothing to do with the Zwave stick and USB, that’s a RPI4 problem. In this case, the network routing just lost it’s mind. Almost as if the network had decided that the device that died was the first step from the hub to all other devices. The nightly heal didn’t work, but I set the heal time to 7PM and by 8PM it was working again so I guess it would have fixed itself eventually. I wish there was a choice at the bottom to just “Network Heal Now” because that was the only sensible thing to try at that moment and it seems the best I can do is set it to run at the next hour and then I have to remember to set it back to the middle of the night.

Ira

Hi Ira, may I ask what are you using for analyzing the network?

It’s a Zwave products Zwave Toolbox. Not sure it adds anything that you can’t do with Openhab itself, but it’s certainly easier for me to see problem in routing and see things like the devices that report in every 15 seconds. I’m sure there are people for whom it’s a lifesaver. It’s $140 or so, so not cheap, but every once in a while it’s stupidly useful if for nothing else that to tell me the network is working or not and maybe like in this case that the routing tables were completely trashed.

Do you know any possibility to see the routing table in OH (without particular ZWave stick for sniffing)?

It is not possible to read the routing table - this can’t be read out of the controller.

1 Like

If you set the heal time to the current hour it will start almost immediately. (Example; If it is 4:40 PM, set to 4PM).

Also fyi I use a the silabs Zniffer to analyze. The UZB was only $35 USD or so and the silabs software is free if you register.

Bob